2025-12-11 00:06:39.877627 | Job console starting...
2025-12-11 00:06:39.888519 | Updating repositories
2025-12-11 00:06:40.032317 | Preparing job workspace
2025-12-11 00:06:43.629379 | Running Ansible setup...
2025-12-11 00:06:48.750987 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-11 00:06:50.958486 | 
2025-12-11 00:06:50.958611 | PLAY [localhost]
2025-12-11 00:06:50.974579 | 
2025-12-11 00:06:50.974747 | TASK [Gathering Facts]
2025-12-11 00:06:51.891746 | localhost | ok
2025-12-11 00:06:51.906398 | 
2025-12-11 00:06:51.906484 | TASK [Setup log path fact]
2025-12-11 00:06:51.934995 | localhost | ok
2025-12-11 00:06:51.947304 | 
2025-12-11 00:06:51.947373 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-11 00:06:51.986987 | localhost | ok
2025-12-11 00:06:51.994763 | 
2025-12-11 00:06:51.994829 | TASK [emit-job-header : Print job information]
2025-12-11 00:06:52.023869 | # Job Information
2025-12-11 00:06:52.024020 | Ansible Version: 2.15.12
2025-12-11 00:06:52.024050 | Job: ansible-test-sanity-docker-devel
2025-12-11 00:06:52.024071 | Pipeline: periodic
2025-12-11 00:06:52.024089 | Executor: ze04.softwarefactory-project.io
2025-12-11 00:06:52.024107 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-12-11 00:06:52.024129 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/abe/ansible/abe4ef872b6646ba8f1d5f3f3fb9f7ae/
2025-12-11 00:06:52.024148 | Event ID: ada59fb35c7242cc951334ebfc65a188
2025-12-11 00:06:52.028299 | 
2025-12-11 00:06:52.028360 | LOOP [emit-job-header : Print node information]
2025-12-11 00:06:52.123491 | localhost | ok:
2025-12-11 00:06:52.123691 | localhost | # Node Information
2025-12-11 00:06:52.123738 | localhost | Inventory Hostname: controller
2025-12-11 00:06:52.123760 | localhost | Hostname: np0005554742
2025-12-11 00:06:52.123783 | localhost | Username: zuul
2025-12-11 00:06:52.123817 | localhost | Distro: Fedora 37
2025-12-11 00:06:52.123839 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-12-11 00:06:52.123857 | localhost | Region: ca-ymq-1
2025-12-11 00:06:52.123873 | localhost | Label: ansible-fedora-37-1vcpu
2025-12-11 00:06:52.123890 | localhost | Product Name: OpenStack Nova
2025-12-11 00:06:52.123907 | localhost | Interface IP: 199.204.45.132
2025-12-11 00:06:52.135097 | 
2025-12-11 00:06:52.135163 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-12-11 00:06:52.544387 | localhost -> localhost | changed
2025-12-11 00:06:52.549792 | 
2025-12-11 00:06:52.549867 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-12-11 00:06:53.359011 | localhost -> localhost | changed
2025-12-11 00:06:53.379344 | 
2025-12-11 00:06:53.379433 | PLAY [all:!appliance*]
2025-12-11 00:06:53.395843 | 
2025-12-11 00:06:53.395951 | TASK [include_role : start-zuul-console]
2025-12-11 00:06:53.425056 | controller | ok
2025-12-11 00:06:53.439146 | 
2025-12-11 00:06:53.439238 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-12-11 00:06:53.815548 | controller | ok
2025-12-11 00:06:53.829663 | 
2025-12-11 00:06:53.829781 | TASK [use-our-mirror : Retrieve the IP address]
2025-12-11 00:06:55.738182 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-12-11 00:06:55.752141 | 
2025-12-11 00:06:55.752291 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-12-11 00:06:56.296162 | controller | skipping: Conditional result was False
2025-12-11 00:06:56.305408 | 
2025-12-11 00:06:56.305509 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-12-11 00:06:56.341258 | controller | skipping: Conditional result was False
2025-12-11 00:06:56.349978 | 
2025-12-11 00:06:56.350065 | TASK [use-our-mirror : Create the podman configuration directory]
2025-12-11 00:06:56.375538 | controller | skipping: Conditional result was False
2025-12-11 00:06:56.381806 | 
2025-12-11 00:06:56.381892 | TASK [use-our-mirror : Copy the podman configuration]
2025-12-11 00:06:56.396114 | controller | skipping: Conditional result was False
2025-12-11 00:06:56.404526 | 
2025-12-11 00:06:56.404626 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-12-11 00:06:56.421713 | controller | skipping: Conditional result was False
2025-12-11 00:06:56.428930 | 
2025-12-11 00:06:56.429033 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-12-11 00:06:56.445910 | controller | skipping: Conditional result was False
2025-12-11 00:06:56.458271 | 
2025-12-11 00:06:56.458375 | TASK [Disable Fedora Modular]
2025-12-11 00:06:56.706129 | controller | changed
2025-12-11 00:06:56.712170 | 
2025-12-11 00:06:56.712241 | TASK [Enable EPEL]
2025-12-11 00:06:56.756414 | controller | skipping: Conditional result was False
2025-12-11 00:06:56.765919 | 
2025-12-11 00:06:56.766026 | TASK [Register the RHEL node]
2025-12-11 00:06:57.315987 | 
2025-12-11 00:06:57.316263 | TASK [Show the subscription-manager status]
2025-12-11 00:06:57.906001 | controller | skipping: Conditional result was False
2025-12-11 00:06:57.919939 | 
2025-12-11 00:06:57.920113 | TASK [Enable EPEL on RHEL]
2025-12-11 00:06:58.474101 | controller | skipping: Conditional result was False
2025-12-11 00:06:58.482517 | 
2025-12-11 00:06:58.482604 | TASK [Install git and tox]
2025-12-11 00:08:32.288815 | controller | changed
2025-12-11 00:08:32.322470 | 
2025-12-11 00:08:32.322632 | TASK [include_role : prepare-workspace]
2025-12-11 00:08:32.356797 | controller | ok
2025-12-11 00:08:32.386195 | 
2025-12-11 00:08:32.386323 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-12-11 00:08:32.636373 | controller | ok
2025-12-11 00:08:32.649998 | 
2025-12-11 00:08:32.650124 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-12-11 00:14:03.072523 | controller | Output suppressed because no_log was given
2025-12-11 00:14:03.095009 | 
2025-12-11 00:14:03.095094 | TASK [include_role : prepare-workspace-openshift]
2025-12-11 00:14:03.121513 | controller | skipping: Conditional result was False
2025-12-11 00:14:03.180470 | 
2025-12-11 00:14:03.180548 | PLAY [all:!appliance]
2025-12-11 00:14:03.196163 | 
2025-12-11 00:14:03.196219 | TASK [Run add-build-sshkey role (RSA)]
2025-12-11 00:14:03.225889 | controller | ok
2025-12-11 00:14:03.241317 | 
2025-12-11 00:14:03.241382 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-11 00:14:03.509076 | controller -> localhost | ok
2025-12-11 00:14:03.516427 | 
2025-12-11 00:14:03.516499 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-11 00:14:03.549833 | controller | ok
2025-12-11 00:14:03.564935 | controller | included: /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-11 00:14:03.571162 | 
2025-12-11 00:14:03.571225 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-11 00:14:04.111320 | controller -> localhost | Generating public/private rsa key pair.
2025-12-11 00:14:04.111911 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/work/abe4ef872b6646ba8f1d5f3f3fb9f7ae_id_rsa.
2025-12-11 00:14:04.111992 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/work/abe4ef872b6646ba8f1d5f3f3fb9f7ae_id_rsa.pub.
2025-12-11 00:14:04.112055 | controller -> localhost | The key fingerprint is:
2025-12-11 00:14:04.112109 | controller -> localhost | SHA256:plErrrAI8IO5D+WHMdVFY1prqxKT8dFeWy++RlaLjNk zuul-build-sshkey
2025-12-11 00:14:04.112165 | controller -> localhost | The key's randomart image is:
2025-12-11 00:14:04.112219 | controller -> localhost | +---[RSA 2048]----+
2025-12-11 00:14:04.112268 | controller -> localhost | |       .*        |
2025-12-11 00:14:04.112320 | controller -> localhost | |     . * o       |
2025-12-11 00:14:04.112369 | controller -> localhost | |    o + = . .    |
2025-12-11 00:14:04.112419 | controller -> localhost | |   . + = + o ..  |
2025-12-11 00:14:04.112475 | controller -> localhost | |. + + + S .=.o.. |
2025-12-11 00:14:04.112545 | controller -> localhost | |.* + + *  o.E..  |
2025-12-11 00:14:04.112608 | controller -> localhost | |= * o +    o.    |
2025-12-11 00:14:04.112670 | controller -> localhost | |.+ = o      ..   |
2025-12-11 00:14:04.112780 | controller -> localhost | |o.o .      ..    |
2025-12-11 00:14:04.112840 | controller -> localhost | +----[SHA256]-----+
2025-12-11 00:14:04.112987 | controller -> localhost | ok: Runtime: 0:00:00.099788
2025-12-11 00:14:04.127832 | 
2025-12-11 00:14:04.127972 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-11 00:14:04.162036 | controller | ok
2025-12-11 00:14:04.176914 | controller | included: /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-11 00:14:04.189651 | 
2025-12-11 00:14:04.189765 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-11 00:14:04.215609 | controller | skipping: Conditional result was False
2025-12-11 00:14:04.225611 | 
2025-12-11 00:14:04.225727 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-11 00:14:04.861284 | controller | changed
2025-12-11 00:14:04.866898 | 
2025-12-11 00:14:04.866961 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-11 00:14:05.102805 | controller | ok
2025-12-11 00:14:05.118836 | 
2025-12-11 00:14:05.119013 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-11 00:14:05.772604 | controller | changed
2025-12-11 00:14:05.786345 | 
2025-12-11 00:14:05.786487 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-11 00:14:06.420672 | controller | changed
2025-12-11 00:14:06.433985 | 
2025-12-11 00:14:06.434120 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-11 00:14:06.462674 | controller | skipping: Conditional result was False
2025-12-11 00:14:06.477807 | 
2025-12-11 00:14:06.477957 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-11 00:14:06.893499 | controller -> localhost | changed
2025-12-11 00:14:06.922622 | 
2025-12-11 00:14:06.922774 | TASK [add-build-sshkey : Add back temp key]
2025-12-11 00:14:07.232845 | controller -> localhost | Identity added: /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/work/abe4ef872b6646ba8f1d5f3f3fb9f7ae_id_rsa (zuul-build-sshkey)
2025-12-11 00:14:07.233338 | controller -> localhost | ok: Runtime: 0:00:00.013940
2025-12-11 00:14:07.249273 | 
2025-12-11 00:14:07.249419 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-11 00:14:07.646579 | controller | ok
2025-12-11 00:14:07.659320 | 
2025-12-11 00:14:07.659459 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-11 00:14:07.686779 | controller | skipping: Conditional result was False
2025-12-11 00:14:07.715749 | 
2025-12-11 00:14:07.715900 | TASK [Run add-build-sshkey role (ECDSA)]
2025-12-11 00:14:07.749827 | controller | ok
2025-12-11 00:14:07.776075 | 
2025-12-11 00:14:07.776199 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-11 00:14:08.046892 | controller -> localhost | ok
2025-12-11 00:14:08.063360 | 
2025-12-11 00:14:08.063523 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-11 00:14:08.105321 | controller | ok
2025-12-11 00:14:08.128785 | controller | included: /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-11 00:14:08.139263 | 
2025-12-11 00:14:08.139362 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-11 00:14:08.439485 | controller -> localhost | Generating public/private ecdsa key pair.
2025-12-11 00:14:08.439714 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/work/abe4ef872b6646ba8f1d5f3f3fb9f7ae_id_ecdsa.
2025-12-11 00:14:08.439760 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/work/abe4ef872b6646ba8f1d5f3f3fb9f7ae_id_ecdsa.pub.
2025-12-11 00:14:08.439803 | controller -> localhost | The key fingerprint is:
2025-12-11 00:14:08.439833 | controller -> localhost | SHA256:bssMjZULhvLdnYmgYL6INgQsyFc57eYuXZFsPpKzpH4 zuul-build-sshkey
2025-12-11 00:14:08.439862 | controller -> localhost | The key's randomart image is:
2025-12-11 00:14:08.439889 | controller -> localhost | +---[ECDSA 521]---+
2025-12-11 00:14:08.439916 | controller -> localhost | |      o          |
2025-12-11 00:14:08.439942 | controller -> localhost | |     + .         |
2025-12-11 00:14:08.439968 | controller -> localhost | |+   . o . .      |
2025-12-11 00:14:08.439994 | controller -> localhost | |+o . . o *       |
2025-12-11 00:14:08.440020 | controller -> localhost | |o = . * S .      |
2025-12-11 00:14:08.440045 | controller -> localhost | | + + + # B o     |
2025-12-11 00:14:08.440070 | controller -> localhost | |. . o O % =      |
2025-12-11 00:14:08.440095 | controller -> localhost | |.+ . o E .       |
2025-12-11 00:14:08.440121 | controller -> localhost | |+ o ..o +        |
2025-12-11 00:14:08.440183 | controller -> localhost | +----[SHA256]-----+
2025-12-11 00:14:08.440257 | controller -> localhost | ok: Runtime: 0:00:00.014064
2025-12-11 00:14:08.450285 | 
2025-12-11 00:14:08.450373 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-11 00:14:08.490157 | controller | ok
2025-12-11 00:14:08.506369 | controller | included: /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-11 00:14:08.520019 | 
2025-12-11 00:14:08.520188 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-11 00:14:08.545811 | controller | skipping: Conditional result was False
2025-12-11 00:14:08.555438 | 
2025-12-11 00:14:08.555525 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-11 00:14:08.843189 | controller | changed
2025-12-11 00:14:08.857634 | 
2025-12-11 00:14:08.857809 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-11 00:14:09.123767 | controller | ok
2025-12-11 00:14:09.137621 | 
2025-12-11 00:14:09.137793 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-11 00:14:09.873204 | controller | changed
2025-12-11 00:14:09.887052 | 
2025-12-11 00:14:09.887191 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-11 00:14:10.622537 | controller | changed
2025-12-11 00:14:10.638087 | 
2025-12-11 00:14:10.638245 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-11 00:14:10.667627 | controller | skipping: Conditional result was False
2025-12-11 00:14:10.683264 | 
2025-12-11 00:14:10.683401 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-11 00:14:10.947247 | controller -> localhost | changed
2025-12-11 00:14:10.987185 | 
2025-12-11 00:14:10.987302 | TASK [add-build-sshkey : Add back temp key]
2025-12-11 00:14:11.329200 | controller -> localhost | Identity added: /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/work/abe4ef872b6646ba8f1d5f3f3fb9f7ae_id_ecdsa (zuul-build-sshkey)
2025-12-11 00:14:11.329717 | controller -> localhost | ok: Runtime: 0:00:00.013468
2025-12-11 00:14:11.344421 | 
2025-12-11 00:14:11.344549 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-11 00:14:11.572650 | controller | ok
2025-12-11 00:14:11.578852 | 
2025-12-11 00:14:11.578921 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-11 00:14:11.624385 | controller | skipping: Conditional result was False
2025-12-11 00:14:11.644852 | 
2025-12-11 00:14:11.644987 | TASK [include_role : remove-zuul-sshkey]
2025-12-11 00:14:11.660187 | controller | skipping: Conditional result was False
2025-12-11 00:14:11.670050 | 
2025-12-11 00:14:11.670159 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-12-11 00:14:11.903506 | controller | ok: "logs"
2025-12-11 00:14:11.904155 | controller | ok: All items complete
2025-12-11 00:14:11.904233 | 
2025-12-11 00:14:12.112524 | controller | ok: "artifacts"
2025-12-11 00:14:12.303484 | controller | ok: "docs"
2025-12-11 00:14:12.327155 | 
2025-12-11 00:14:12.327313 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-12-11 00:14:12.561537 | controller | changed: "logs"
2025-12-11 00:14:12.794864 | controller | changed: "artifacts"
2025-12-11 00:14:13.034420 | controller | changed: "docs"
2025-12-11 00:14:13.096825 | 
2025-12-11 00:14:13.096918 | PLAY RECAP
2025-12-11 00:14:13.096973 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-12-11 00:14:13.097009 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-11 00:14:13.097058 | 
2025-12-11 00:14:13.230045 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-11 00:14:13.231750 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-11 00:14:13.844504 | 
2025-12-11 00:14:13.844639 | PLAY [all]
2025-12-11 00:14:13.868581 | 
2025-12-11 00:14:13.868715 | TASK [Install binary dependencies]
2025-12-11 00:14:13.941753 | controller | ok
2025-12-11 00:14:13.972502 | 
2025-12-11 00:14:13.972642 | TASK [bindep : Include find tasks]
2025-12-11 00:14:14.007091 | controller | ok
2025-12-11 00:14:14.019547 | controller | included: /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-12-11 00:14:14.029306 | 
2025-12-11 00:14:14.029401 | TASK [bindep : Look for bindep.txt]
2025-12-11 00:14:14.600276 | controller | ok
2025-12-11 00:14:14.615225 | 
2025-12-11 00:14:14.615387 | TASK [bindep : Define bindep_file fact]
2025-12-11 00:14:14.632996 | controller | skipping: Conditional result was False
2025-12-11 00:14:14.648625 | 
2025-12-11 00:14:14.648831 | TASK [bindep : Look for other-requirements.txt]
2025-12-11 00:14:14.873815 | controller | ok
2025-12-11 00:14:14.888789 | 
2025-12-11 00:14:14.888999 | TASK [bindep : Define bindep_file fact]
2025-12-11 00:14:14.918156 | controller | skipping: Conditional result was False
2025-12-11 00:14:14.932031 | 
2025-12-11 00:14:14.932129 | TASK [bindep : Look for bindep fallback file]
2025-12-11 00:14:14.978458 | controller | skipping: Conditional result was False
2025-12-11 00:14:14.989827 | 
2025-12-11 00:14:14.989947 | TASK [bindep : Define bindep_file fact]
2025-12-11 00:14:15.026327 | controller | skipping: Conditional result was False
2025-12-11 00:14:15.035594 | 
2025-12-11 00:14:15.035715 | TASK [bindep : Include bindep tasks]
2025-12-11 00:14:15.071110 | controller | skipping: Conditional result was False
2025-12-11 00:14:15.080803 | 
2025-12-11 00:14:15.080900 | TASK [bindep : Include install tasks]
2025-12-11 00:14:15.105624 | controller | skipping: Conditional result was False
2025-12-11 00:14:15.115042 | 
2025-12-11 00:14:15.115139 | LOOP [bindep : Include package tasks]
2025-12-11 00:14:15.205048 | 
2025-12-11 00:14:15.205397 | TASK [Run test-setup role]
2025-12-11 00:14:15.235078 | controller | ok
2025-12-11 00:14:15.260203 | 
2025-12-11 00:14:15.260293 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-12-11 00:14:15.487016 | controller | ok
2025-12-11 00:14:15.496174 | 
2025-12-11 00:14:15.496263 | TASK [test-setup : Run tools/test-setup.sh]
2025-12-11 00:14:16.044825 | controller | skipping: Conditional result was False
2025-12-11 00:14:16.101536 | 
2025-12-11 00:14:16.101648 | PLAY RECAP
2025-12-11 00:14:16.101721 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-11 00:14:16.101754 | 
2025-12-11 00:14:16.208724 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-11 00:14:16.209578 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-11 00:14:16.796531 | 
2025-12-11 00:14:16.796659 | PLAY [controller]
2025-12-11 00:14:16.818994 | 
2025-12-11 00:14:16.819151 | TASK [Create the /root directory]
2025-12-11 00:14:17.437152 | controller | ok
2025-12-11 00:14:17.451360 | 
2025-12-11 00:14:17.451535 | TASK [Install glibc-langpack-en]
2025-12-11 00:14:21.552556 | controller | ok: Nothing to do
2025-12-11 00:14:21.565335 | 
2025-12-11 00:14:21.565472 | TASK [Ensure controller directory exists]
2025-12-11 00:14:21.825145 | controller | changed
2025-12-11 00:14:21.834238 | 
2025-12-11 00:14:21.834338 | TASK [Install container runtime]
2025-12-11 00:14:21.882953 | controller | ok
2025-12-11 00:14:21.941770 | 
2025-12-11 00:14:21.941914 | LOOP [ensure-podman : Find distribution installation]
2025-12-11 00:14:21.968839 | controller | ok: "/var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-12-11 00:14:21.989173 | controller | included: /var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-12-11 00:14:21.999041 | 
2025-12-11 00:14:21.999141 | TASK [ensure-podman : Install podman (RedHat)]
2025-12-11 00:15:30.961388 | controller | changed
2025-12-11 00:15:30.968043 | 
2025-12-11 00:15:30.968105 | TASK [ensure-podman : Fetch podman version]
2025-12-11 00:15:31.506162 | controller | Client:       Podman Engine
2025-12-11 00:15:31.536252 | controller | Version:      4.6.2
2025-12-11 00:15:31.536295 | controller | API Version:  4.6.2
2025-12-11 00:15:31.536308 | controller | Go Version:   go1.19.12
2025-12-11 00:15:31.536333 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-12-11 00:15:31.536345 | controller | OS/Arch:      linux/amd64
2025-12-11 00:15:32.002273 | controller | ok: Runtime: 0:00:00.198073
2025-12-11 00:15:32.021585 | 
2025-12-11 00:15:32.021769 | TASK [ensure-podman : Print podman version installed]
2025-12-11 00:15:32.055651 | Podman version: Client:       Podman Engine
2025-12-11 00:15:32.055845 | Version:      4.6.2
2025-12-11 00:15:32.055885 | API Version:  4.6.2
2025-12-11 00:15:32.055914 | Go Version:   go1.19.12
2025-12-11 00:15:32.055940 | Built:        Mon Aug 28 19:38:31 2023
2025-12-11 00:15:32.055969 | OS/Arch:      linux/amd64
2025-12-11 00:15:32.063383 | 
2025-12-11 00:15:32.063462 | TASK [ensure-podman : Validate podman engine]
2025-12-11 00:15:32.602283 | controller | skipping: Conditional result was False
2025-12-11 00:15:32.616232 | 
2025-12-11 00:15:32.616375 | TASK [ensure-podman : Set up docker compatability socket]
2025-12-11 00:15:32.653249 | controller | skipping: Conditional result was False
2025-12-11 00:15:32.682013 | 
2025-12-11 00:15:32.682158 | TASK [Ensure python3.8 is present]
2025-12-11 00:15:32.707867 | controller | skipping: Conditional result was False
2025-12-11 00:15:32.715880 | 
2025-12-11 00:15:32.715980 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-12-11 00:15:32.739907 | controller | ok
2025-12-11 00:15:32.767443 | 
2025-12-11 00:15:32.767552 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-12-11 00:15:34.500022 | controller | ok: Nothing to do
2025-12-11 00:15:34.514005 | 
2025-12-11 00:15:34.514151 | TASK [our-ensure-python : Also install python3-devel]
2025-12-11 00:15:44.444785 | controller | changed
2025-12-11 00:15:44.467062 | 
2025-12-11 00:15:44.467268 | TASK [Run ensure-virtualenv role]
2025-12-11 00:15:44.500974 | controller | ok
2025-12-11 00:15:44.532211 | 
2025-12-11 00:15:44.532373 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-12-11 00:15:44.780938 | controller | /usr/bin/virtualenv
2025-12-11 00:15:45.094855 | controller | ok: Runtime: 0:00:00.004358
2025-12-11 00:15:45.103211 | 
2025-12-11 00:15:45.103297 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-12-11 00:15:45.128023 | controller | skipping: Conditional result was False
2025-12-11 00:15:45.128320 | controller | ok: All items complete
2025-12-11 00:15:45.128349 | 
2025-12-11 00:15:45.145655 | 
2025-12-11 00:15:45.145801 | TASK [Find the full path of the Python interpreter]
2025-12-11 00:15:45.370059 | controller | /usr/bin/python3
2025-12-11 00:15:45.686222 | controller | ok
2025-12-11 00:15:45.699497 | 
2025-12-11 00:15:45.699658 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-12-11 00:15:46.636995 | controller | created virtual environment CPython3.11.0.final.0-64 in 497ms
2025-12-11 00:15:46.656000 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-12-11 00:15:46.656038 | 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/.local/share/virtualenv)
2025-12-11 00:15:46.656047 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-12-11 00:15:46.656061 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-12-11 00:15:46.766824 | controller | changed
2025-12-11 00:15:46.777031 | 
2025-12-11 00:15:46.777097 | TASK [Set selinux package]
2025-12-11 00:15:46.808728 | controller | ok
2025-12-11 00:15:46.813869 | 
2025-12-11 00:15:46.813932 | TASK [Set selinux package (Fedora)]
2025-12-11 00:15:46.863620 | controller | ok
2025-12-11 00:15:46.869336 | 
2025-12-11 00:15:46.869405 | TASK [Install selinux into virtualenv]
2025-12-11 00:16:12.375525 | controller | Collecting selinux-please-lie-to-me
2025-12-11 00:16:24.614041 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-12-11 00:16:24.925721 | controller | Collecting setuptools<50.0.0
2025-12-11 00:16:24.930826 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-12-11 00:16:24.970964 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.2 MB/s eta 0:00:00
2025-12-11 00:16:25.051412 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-12-11 00:16:25.051511 | controller |   Attempting uninstall: setuptools
2025-12-11 00:16:25.054225 | controller |     Found existing installation: setuptools 62.6.0
2025-12-11 00:16:25.114506 | controller |     Uninstalling setuptools-62.6.0:
2025-12-11 00:16:25.122361 | controller |       Successfully uninstalled setuptools-62.6.0
2025-12-11 00:16:25.483453 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-12-11 00:16:36.987923 | controller |
2025-12-11 00:16:37.064610 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-11 00:16:37.064652 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-11 00:16:37.444333 | controller | ok: Runtime: 0:00:49.973756
2025-12-11 00:16:37.457773 | 
2025-12-11 00:16:37.457917 | TASK [Install pytest-forked into virtualenv]
2025-12-11 00:16:49.288584 | controller | Collecting pytest-forked
2025-12-11 00:17:13.569835 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-12-11 00:17:13.619829 | controller | Collecting py
2025-12-11 00:17:13.623100 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-12-11 00:17:13.642481 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 6.1 MB/s eta 0:00:00
2025-12-11 00:17:13.752125 | controller | Collecting pytest>=3.10
2025-12-11 00:17:13.762467 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2025-12-11 00:17:13.777058 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 33.7 MB/s eta 0:00:00
2025-12-11 00:17:13.816247 | controller | Collecting iniconfig>=1.0.1
2025-12-11 00:17:13.819669 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-12-11 00:17:13.865401 | controller | Collecting packaging>=22
2025-12-11 00:17:13.868223 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-12-11 00:17:13.876135 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.7 MB/s eta 0:00:00
2025-12-11 00:17:13.910292 | controller | Collecting pluggy<2,>=1.5
2025-12-11 00:17:13.913221 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-12-11 00:17:13.965751 | controller | Collecting pygments>=2.7.2
2025-12-11 00:17:13.968577 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-12-11 00:17:13.985760 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 84.7 MB/s eta 0:00:00
2025-12-11 00:17:14.054101 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-12-11 00:17:15.085220 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0
2025-12-11 00:17:15.093602 | controller |
2025-12-11 00:17:15.159207 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-11 00:17:15.159261 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-11 00:17:15.530403 | controller | ok: Runtime: 0:00:37.469179
2025-12-11 00:17:15.546549 | 
2025-12-11 00:17:15.546758 | TASK [Update pip]
2025-12-11 00:17:16.086078 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-12-11 00:17:25.952119 | controller | Collecting pip
2025-12-11 00:17:38.151352 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-12-11 00:17:38.208468 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 34.7 MB/s eta 0:00:00
2025-12-11 00:17:38.272321 | controller | Installing collected packages: pip
2025-12-11 00:17:38.272479 | controller |   Attempting uninstall: pip
2025-12-11 00:17:38.274618 | controller |     Found existing installation: pip 22.2.2
2025-12-11 00:17:38.407799 | controller |     Uninstalling pip-22.2.2:
2025-12-11 00:17:38.422374 | controller |       Successfully uninstalled pip-22.2.2
2025-12-11 00:17:39.226486 | controller | Successfully installed pip-25.3
2025-12-11 00:17:39.614086 | controller | ok: Runtime: 0:00:23.520565
2025-12-11 00:17:39.627541 | 
2025-12-11 00:17:39.627753 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-12-11 00:17:39.861249 | controller | changed
2025-12-11 00:17:39.869540 | 
2025-12-11 00:17:39.869630 | TASK [Install ansible into virtualenv]
2025-12-11 00:17:40.398552 | controller | Processing ./src/github.com/ansible/ansible
2025-12-11 00:17:40.401902 | controller |   Installing build dependencies: started
2025-12-11 00:18:00.996334 | controller |   Installing build dependencies: finished with status 'done'
2025-12-11 00:18:00.996989 | controller |   Getting requirements to build wheel: started
2025-12-11 00:18:01.740597 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-12-11 00:18:01.741935 | controller |   Preparing metadata (pyproject.toml): started
2025-12-11 00:18:02.199263 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-12-11 00:18:02.204613 | 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-12-11 00:18:02.208961 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-12-11 00:18:02.453568 | controller | ERROR
2025-12-11 00:18:02.453853 | controller | {
2025-12-11 00:18:02.453932 | controller |   "delta": "0:00:22.150143",
2025-12-11 00:18:02.453979 | controller |   "end": "2025-12-11 00:18:02.266091",
2025-12-11 00:18:02.454020 | controller |   "msg": "non-zero return code",
2025-12-11 00:18:02.454078 | controller |   "rc": 1,
2025-12-11 00:18:02.454118 | controller |   "start": "2025-12-11 00:17:40.115948"
2025-12-11 00:18:02.454154 | controller | }
failure
2025-12-11 00:18:02.457329 | 
2025-12-11 00:18:02.457730 | PLAY RECAP
2025-12-11 00:18:02.457872 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-12-11 00:18:02.457923 | 
2025-12-11 00:18:02.602130 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-11 00:18:02.603553 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-11 00:18:03.189479 | 
2025-12-11 00:18:03.189591 | PLAY [all]
2025-12-11 00:18:03.211818 | 
2025-12-11 00:18:03.211933 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-12-11 00:18:03.635530 | controller | changed: non-zero return code
2025-12-11 00:18:03.648701 | 
2025-12-11 00:18:03.648871 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-12-11 00:18:03.676433 | controller | skipping: Conditional result was False
2025-12-11 00:18:03.690099 | 
2025-12-11 00:18:03.690277 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-12-11 00:18:03.733552 | 
2025-12-11 00:18:03.733868 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-12-11 00:18:03.774148 | 
2025-12-11 00:18:03.774424 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-12-11 00:18:03.801123 | controller | skipping: Conditional result was False
2025-12-11 00:18:03.817807 | 
2025-12-11 00:18:03.817986 | LOOP [fetch-subunit-output : Generate subunit file]
2025-12-11 00:18:03.858153 | 
2025-12-11 00:18:03.858432 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-12-11 00:18:03.885507 | controller | skipping: Conditional result was False
2025-12-11 00:18:03.898532 | 
2025-12-11 00:18:03.898758 | TASK [fetch-subunit-output : Remove the temporary file]
2025-12-11 00:18:03.926200 | controller | skipping: Conditional result was False
2025-12-11 00:18:03.939979 | 
2025-12-11 00:18:03.940135 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-12-11 00:18:03.967320 | controller | skipping: Conditional result was False
2025-12-11 00:18:04.016187 | 
2025-12-11 00:18:04.016390 | PLAY RECAP
2025-12-11 00:18:04.016456 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-11 00:18:04.016486 | 
2025-12-11 00:18:04.113305 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-11 00:18:04.114187 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-12-11 00:18:04.690980 | 
2025-12-11 00:18:04.691097 | PLAY [all:!appliance*]
2025-12-11 00:18:04.712433 | 
2025-12-11 00:18:04.712522 | TASK [unregister the node]
2025-12-11 00:18:05.243851 | controller | skipping: Conditional result was False
2025-12-11 00:18:05.256494 | 
2025-12-11 00:18:05.256657 | TASK [include_role : fetch-output]
2025-12-11 00:18:05.306848 | controller | ok
2025-12-11 00:18:05.351643 | 
2025-12-11 00:18:05.351801 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-11 00:18:05.427826 | controller | skipping: Conditional result was False
2025-12-11 00:18:05.436655 | 
2025-12-11 00:18:05.436773 | TASK [fetch-output : Set log path for single node]
2025-12-11 00:18:05.489918 | controller | ok
2025-12-11 00:18:05.498111 | 
2025-12-11 00:18:05.498199 | LOOP [fetch-output : Ensure local output dirs]
2025-12-11 00:18:06.011086 | controller -> localhost | ok: "/var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/work/logs"
2025-12-11 00:18:06.265158 | controller -> localhost | changed: "/var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/work/artifacts"
2025-12-11 00:18:06.466323 | controller -> localhost | changed: "/var/lib/zuul/builds/abe4ef872b6646ba8f1d5f3f3fb9f7ae/work/docs"
2025-12-11 00:18:06.486107 | 
2025-12-11 00:18:06.486289 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-11 00:18:07.221131 | controller | changed:
2025-12-11 00:18:07.221545 | controller | .d..t...... ./
2025-12-11 00:18:07.221608 | controller | cd+++++++++ controller/
2025-12-11 00:18:07.221673 | controller | changed: All items complete
2025-12-11 00:18:07.221761 | 
2025-12-11 00:18:07.768356 | controller | changed: .d..t...... ./
2025-12-11 00:18:08.265851 | controller | changed: .d..t...... ./
2025-12-11 00:18:08.297146 | 
2025-12-11 00:18:08.297354 | TASK [include_role : fetch-output-openshift]
2025-12-11 00:18:08.314343 | controller | skipping: Conditional result was False
2025-12-11 00:18:08.326072 | 
2025-12-11 00:18:08.326181 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-12-11 00:18:08.369720 | controller | skipping: Conditional result was False
2025-12-11 00:18:08.381795 | controller | skipping: Conditional result was False
2025-12-11 00:18:08.433995 | 
2025-12-11 00:18:08.434135 | PLAY [localhost]
2025-12-11 00:18:08.452175 | 
2025-12-11 00:18:08.452283 | TASK [Run Zuul manifest role]
2025-12-11 00:18:08.474389 | localhost | ok
2025-12-11 00:18:08.495225 | 
2025-12-11 00:18:08.495314 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-12-11 00:18:08.953380 | localhost | changed
2025-12-11 00:18:08.958269 | 
2025-12-11 00:18:08.958332 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-12-11 00:18:08.986656 | localhost | ok
2025-12-11 00:18:08.994243 | 
2025-12-11 00:18:08.994301 | TASK [Set zuul-log-path fact]
2025-12-11 00:18:09.011987 | localhost | ok
2025-12-11 00:18:09.025940 | 
2025-12-11 00:18:09.026005 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-11 00:18:09.064957 | localhost | ok
2025-12-11 00:18:09.072836 | 
2025-12-11 00:18:09.072895 | LOOP [Run upload-logs-swift role]
2025-12-11 00:18:09.106653 | localhost | Output suppressed because no_log was given
2025-12-11 00:18:09.131331 | 
2025-12-11 00:18:09.131394 | TASK [Set zuul-log-path fact]
2025-12-11 00:18:09.165757 | localhost | skipping: Conditional result was False
2025-12-11 00:18:09.171295 | 
2025-12-11 00:18:09.171359 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-12-11 00:18:09.577837 | localhost -> localhost | ok: Runtime: 0:00:00.009361
2025-12-11 00:18:09.621632 | 
2025-12-11 00:18:09.621793 | TASK [upload-logs-swift : Upload logs to swift]