2025-09-30 00:22:12.410338 | Job console starting...
2025-09-30 00:22:12.420176 | Updating repositories
2025-09-30 00:22:12.551045 | Preparing job workspace
2025-09-30 00:22:16.142267 | Running Ansible setup...
2025-09-30 00:22:24.913259 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-30 00:22:25.610429 | 
2025-09-30 00:22:25.610581 | PLAY [localhost]
2025-09-30 00:22:25.624360 | 
2025-09-30 00:22:25.624487 | TASK [Gathering Facts]
2025-09-30 00:22:26.745274 | localhost | ok
2025-09-30 00:22:26.765989 | 
2025-09-30 00:22:26.766190 | TASK [Setup log path fact]
2025-09-30 00:22:26.786192 | localhost | ok
2025-09-30 00:22:26.798600 | 
2025-09-30 00:22:26.798700 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 00:22:26.827856 | localhost | ok
2025-09-30 00:22:26.835770 | 
2025-09-30 00:22:26.835846 | TASK [emit-job-header : Print job information]
2025-09-30 00:22:26.866889 | # Job Information
2025-09-30 00:22:26.867145 | Ansible Version: 2.15.12
2025-09-30 00:22:26.867201 | Job: ansible-test-sanity-docker-devel
2025-09-30 00:22:26.867237 | Pipeline: periodic
2025-09-30 00:22:26.867258 | Executor: ze01.softwarefactory-project.io
2025-09-30 00:22:26.867281 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-30 00:22:26.867311 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/309/ansible/309e105a6f4744f5be0752d8cff34c03/
2025-09-30 00:22:26.867335 | Event ID: 8b4cd1603b324f4bbcbe8377ef9bcb18
2025-09-30 00:22:26.871767 | 
2025-09-30 00:22:26.871855 | LOOP [emit-job-header : Print node information]
2025-09-30 00:22:26.972273 | localhost | ok:
2025-09-30 00:22:26.972476 | localhost | # Node Information
2025-09-30 00:22:26.972509 | localhost | Inventory Hostname: controller
2025-09-30 00:22:26.972533 | localhost | Hostname: np0005461109
2025-09-30 00:22:26.972558 | localhost | Username: zuul
2025-09-30 00:22:26.972585 | localhost | Distro: Fedora 37
2025-09-30 00:22:26.972608 | localhost | Provider: ansible-vexxhost-ams1
2025-09-30 00:22:26.972631 | localhost | Region: ams1
2025-09-30 00:22:26.972653 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-30 00:22:26.972675 | localhost | Product Name: OpenStack Nova
2025-09-30 00:22:26.972697 | localhost | Interface IP: 38.129.16.8
2025-09-30 00:22:26.991185 | 
2025-09-30 00:22:26.991343 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-30 00:22:27.396545 | localhost -> localhost | changed
2025-09-30 00:22:27.403282 | 
2025-09-30 00:22:27.403370 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-30 00:22:28.311722 | localhost -> localhost | changed
2025-09-30 00:22:28.333523 | 
2025-09-30 00:22:28.333601 | PLAY [all:!appliance*]
2025-09-30 00:22:28.351447 | 
2025-09-30 00:22:28.351596 | TASK [include_role : start-zuul-console]
2025-09-30 00:22:28.374785 | controller | ok
2025-09-30 00:22:28.390738 | 
2025-09-30 00:22:28.390850 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-30 00:22:29.512046 | controller | ok
2025-09-30 00:22:29.525955 | 
2025-09-30 00:22:29.526110 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-30 00:22:32.067179 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-30 00:22:32.082788 | 
2025-09-30 00:22:32.082968 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-30 00:22:32.463524 | controller | skipping: Conditional result was False
2025-09-30 00:22:32.472417 | 
2025-09-30 00:22:32.472539 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-30 00:22:32.509183 | controller | skipping: Conditional result was False
2025-09-30 00:22:32.521409 | 
2025-09-30 00:22:32.521540 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-30 00:22:32.547763 | controller | skipping: Conditional result was False
2025-09-30 00:22:32.557280 | 
2025-09-30 00:22:32.557408 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-30 00:22:32.583765 | controller | skipping: Conditional result was False
2025-09-30 00:22:32.593493 | 
2025-09-30 00:22:32.593608 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-30 00:22:32.620042 | controller | skipping: Conditional result was False
2025-09-30 00:22:32.630599 | 
2025-09-30 00:22:32.630744 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-30 00:22:32.646301 | controller | skipping: Conditional result was False
2025-09-30 00:22:32.666807 | 
2025-09-30 00:22:32.666954 | TASK [Disable Fedora Modular]
2025-09-30 00:22:33.985785 | controller | changed
2025-09-30 00:22:34.000208 | 
2025-09-30 00:22:34.000384 | TASK [Enable EPEL]
2025-09-30 00:22:34.031997 | controller | skipping: Conditional result was False
2025-09-30 00:22:34.050503 | 
2025-09-30 00:22:34.050725 | TASK [Register the RHEL node]
2025-09-30 00:22:34.466086 | 
2025-09-30 00:22:34.466309 | TASK [Show the subscription-manager status]
2025-09-30 00:22:34.832853 | controller | skipping: Conditional result was False
2025-09-30 00:22:34.840529 | 
2025-09-30 00:22:34.840660 | TASK [Enable EPEL on RHEL]
2025-09-30 00:22:35.213652 | controller | skipping: Conditional result was False
2025-09-30 00:22:35.221325 | 
2025-09-30 00:22:35.221456 | TASK [Install git and tox]
2025-09-30 00:25:11.802209 | controller | changed
2025-09-30 00:25:11.818015 | 
2025-09-30 00:25:11.818234 | TASK [include_role : prepare-workspace]
2025-09-30 00:25:11.855060 | controller | ok
2025-09-30 00:25:11.888903 | 
2025-09-30 00:25:11.889079 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-30 00:25:12.849988 | controller | ok
2025-09-30 00:25:12.862233 | 
2025-09-30 00:25:12.862384 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-30 00:25:28.825279 | controller | Output suppressed because no_log was given
2025-09-30 00:25:28.846360 | 
2025-09-30 00:25:28.846485 | TASK [include_role : prepare-workspace-openshift]
2025-09-30 00:25:28.871512 | controller | skipping: Conditional result was False
2025-09-30 00:25:28.895166 | 
2025-09-30 00:25:28.895265 | PLAY [all:!appliance]
2025-09-30 00:25:28.911953 | 
2025-09-30 00:25:28.912103 | TASK [Run add-build-sshkey role (RSA)]
2025-09-30 00:25:28.942411 | controller | ok
2025-09-30 00:25:28.957970 | 
2025-09-30 00:25:28.958105 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-30 00:25:29.216832 | controller -> localhost | ok
2025-09-30 00:25:29.223325 | 
2025-09-30 00:25:29.223425 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-30 00:25:29.252896 | controller | ok
2025-09-30 00:25:29.267312 | controller | included: /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-30 00:25:29.274524 | 
2025-09-30 00:25:29.274661 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-30 00:25:29.759253 | controller -> localhost | Generating public/private rsa key pair.
2025-09-30 00:25:29.759477 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/work/309e105a6f4744f5be0752d8cff34c03_id_rsa.
2025-09-30 00:25:29.759508 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/work/309e105a6f4744f5be0752d8cff34c03_id_rsa.pub.
2025-09-30 00:25:29.759529 | controller -> localhost | The key fingerprint is:
2025-09-30 00:25:29.759548 | controller -> localhost | SHA256:3FseLCpRjwpgKfoTijGsT9oeu4GwX8ivv+p0xoDNbnI zuul-build-sshkey
2025-09-30 00:25:29.759567 | controller -> localhost | The key's randomart image is:
2025-09-30 00:25:29.759585 | controller -> localhost | +---[RSA 2048]----+
2025-09-30 00:25:29.759603 | controller -> localhost | |                 |
2025-09-30 00:25:29.759621 | controller -> localhost | |   .             |
2025-09-30 00:25:29.759639 | controller -> localhost | |. +     .        |
2025-09-30 00:25:29.759655 | controller -> localhost | |o* .   o + .     |
2025-09-30 00:25:29.759672 | controller -> localhost | |*.= . . S + +    |
2025-09-30 00:25:29.759700 | controller -> localhost | |+X = . o . = .   |
2025-09-30 00:25:29.759725 | controller -> localhost | |B E = o . . .    |
2025-09-30 00:25:29.759744 | controller -> localhost | | @ X   .         |
2025-09-30 00:25:29.759761 | controller -> localhost | |.o@=+.           |
2025-09-30 00:25:29.759782 | controller -> localhost | +----[SHA256]-----+
2025-09-30 00:25:29.759833 | controller -> localhost | ok: Runtime: 0:00:00.100814
2025-09-30 00:25:29.770772 | 
2025-09-30 00:25:29.770913 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-30 00:25:29.809961 | controller | ok
2025-09-30 00:25:29.820939 | controller | included: /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-30 00:25:29.831353 | 
2025-09-30 00:25:29.831459 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-30 00:25:29.846617 | controller | skipping: Conditional result was False
2025-09-30 00:25:29.854308 | 
2025-09-30 00:25:29.854449 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-30 00:25:31.041837 | controller | changed
2025-09-30 00:25:31.051405 | 
2025-09-30 00:25:31.051548 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-30 00:25:31.713183 | controller | ok
2025-09-30 00:25:31.724107 | 
2025-09-30 00:25:31.724258 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-30 00:25:34.885473 | controller | changed
2025-09-30 00:25:34.891940 | 
2025-09-30 00:25:34.892043 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-30 00:25:38.010819 | controller | changed
2025-09-30 00:25:38.019513 | 
2025-09-30 00:25:38.019618 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-30 00:25:38.044795 | controller | skipping: Conditional result was False
2025-09-30 00:25:38.052747 | 
2025-09-30 00:25:38.052831 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-30 00:25:38.506871 | controller -> localhost | changed
2025-09-30 00:25:38.541432 | 
2025-09-30 00:25:38.541663 | TASK [add-build-sshkey : Add back temp key]
2025-09-30 00:25:38.833920 | controller -> localhost | Identity added: /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/work/309e105a6f4744f5be0752d8cff34c03_id_rsa (zuul-build-sshkey)
2025-09-30 00:25:38.834166 | controller -> localhost | ok: Runtime: 0:00:00.008254
2025-09-30 00:25:38.841653 | 
2025-09-30 00:25:38.841723 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-30 00:25:39.804095 | controller | ok
2025-09-30 00:25:39.809994 | 
2025-09-30 00:25:39.810282 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-30 00:25:39.835880 | controller | skipping: Conditional result was False
2025-09-30 00:25:39.850997 | 
2025-09-30 00:25:39.851168 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-30 00:25:39.871757 | controller | ok
2025-09-30 00:25:39.889278 | 
2025-09-30 00:25:39.889659 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-30 00:25:40.129796 | controller -> localhost | ok
2025-09-30 00:25:40.136954 | 
2025-09-30 00:25:40.137135 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-30 00:25:40.168202 | controller | ok
2025-09-30 00:25:40.183110 | controller | included: /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-30 00:25:40.190087 | 
2025-09-30 00:25:40.190164 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-30 00:25:40.459150 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-30 00:25:40.459401 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/work/309e105a6f4744f5be0752d8cff34c03_id_ecdsa.
2025-09-30 00:25:40.459458 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/work/309e105a6f4744f5be0752d8cff34c03_id_ecdsa.pub.
2025-09-30 00:25:40.459506 | controller -> localhost | The key fingerprint is:
2025-09-30 00:25:40.459549 | controller -> localhost | SHA256:R82PC7FxqlzrP46/weWUyl9Fifhqvfuchvn+lV/g6Yw zuul-build-sshkey
2025-09-30 00:25:40.459590 | controller -> localhost | The key's randomart image is:
2025-09-30 00:25:40.459626 | controller -> localhost | +---[ECDSA 521]---+
2025-09-30 00:25:40.459667 | controller -> localhost | |                 |
2025-09-30 00:25:40.459697 | controller -> localhost | |           o. . .|
2025-09-30 00:25:40.459735 | controller -> localhost | |          +.+. ..|
2025-09-30 00:25:40.459768 | controller -> localhost | |         . *.o o |
2025-09-30 00:25:40.459795 | controller -> localhost | |        S * ..* .|
2025-09-30 00:25:40.459821 | controller -> localhost | |       . + =oB oo|
2025-09-30 00:25:40.459849 | controller -> localhost | |        o .o*.*.+|
2025-09-30 00:25:40.459874 | controller -> localhost | |         ....Ooo=|
2025-09-30 00:25:40.459900 | controller -> localhost | |          o+E=X*+|
2025-09-30 00:25:40.459925 | controller -> localhost | +----[SHA256]-----+
2025-09-30 00:25:40.459992 | controller -> localhost | ok: Runtime: 0:00:00.007538
2025-09-30 00:25:40.472401 | 
2025-09-30 00:25:40.472550 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-30 00:25:40.495640 | controller | ok
2025-09-30 00:25:40.503349 | controller | included: /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-30 00:25:40.513521 | 
2025-09-30 00:25:40.513607 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-30 00:25:40.528160 | controller | skipping: Conditional result was False
2025-09-30 00:25:40.576186 | 
2025-09-30 00:25:40.576457 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-30 00:25:41.529850 | controller | changed
2025-09-30 00:25:41.536701 | 
2025-09-30 00:25:41.536777 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-30 00:25:42.247192 | controller | ok
2025-09-30 00:25:42.257854 | 
2025-09-30 00:25:42.258029 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-30 00:25:45.376063 | controller | changed
2025-09-30 00:25:45.382389 | 
2025-09-30 00:25:45.382535 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-30 00:25:48.480364 | controller | changed
2025-09-30 00:25:48.495816 | 
2025-09-30 00:25:48.495959 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-30 00:25:48.526423 | controller | skipping: Conditional result was False
2025-09-30 00:25:48.536136 | 
2025-09-30 00:25:48.536258 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-30 00:25:48.791177 | controller -> localhost | changed
2025-09-30 00:25:48.808797 | 
2025-09-30 00:25:48.808977 | TASK [add-build-sshkey : Add back temp key]
2025-09-30 00:25:49.185555 | controller -> localhost | Identity added: /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/work/309e105a6f4744f5be0752d8cff34c03_id_ecdsa (zuul-build-sshkey)
2025-09-30 00:25:49.185900 | controller -> localhost | ok: Runtime: 0:00:00.009461
2025-09-30 00:25:49.201062 | 
2025-09-30 00:25:49.201264 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-30 00:25:49.929009 | controller | ok
2025-09-30 00:25:49.938274 | 
2025-09-30 00:25:49.938403 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-30 00:25:49.965362 | controller | skipping: Conditional result was False
2025-09-30 00:25:49.983075 | 
2025-09-30 00:25:49.983216 | TASK [include_role : remove-zuul-sshkey]
2025-09-30 00:25:49.998581 | controller | skipping: Conditional result was False
2025-09-30 00:25:50.008968 | 
2025-09-30 00:25:50.009130 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 00:25:50.752810 | controller | ok: "logs"
2025-09-30 00:25:50.753270 | controller | ok: All items complete
2025-09-30 00:25:50.753502 | 
2025-09-30 00:25:51.452346 | controller | ok: "artifacts"
2025-09-30 00:25:52.187788 | controller | ok: "docs"
2025-09-30 00:25:52.202548 | 
2025-09-30 00:25:52.203254 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 00:25:52.930664 | controller | changed: "logs"
2025-09-30 00:25:53.622867 | controller | changed: "artifacts"
2025-09-30 00:25:54.332166 | controller | changed: "docs"
2025-09-30 00:25:54.378209 | 
2025-09-30 00:25:54.378354 | PLAY RECAP
2025-09-30 00:25:54.378420 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-30 00:25:54.378458 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 00:25:54.378481 | 
2025-09-30 00:25:54.516421 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-30 00:25:54.518366 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 00:25:55.189724 | 
2025-09-30 00:25:55.189860 | PLAY [all]
2025-09-30 00:25:55.215514 | 
2025-09-30 00:25:55.215662 | TASK [Install binary dependencies]
2025-09-30 00:25:55.287946 | controller | ok
2025-09-30 00:25:55.318137 | 
2025-09-30 00:25:55.318316 | TASK [bindep : Include find tasks]
2025-09-30 00:25:55.353503 | controller | ok
2025-09-30 00:25:55.365662 | controller | included: /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-30 00:25:55.375902 | 
2025-09-30 00:25:55.376127 | TASK [bindep : Look for bindep.txt]
2025-09-30 00:25:56.373216 | controller | ok
2025-09-30 00:25:56.381923 | 
2025-09-30 00:25:56.382070 | TASK [bindep : Define bindep_file fact]
2025-09-30 00:25:56.397245 | controller | skipping: Conditional result was False
2025-09-30 00:25:56.404584 | 
2025-09-30 00:25:56.404720 | TASK [bindep : Look for other-requirements.txt]
2025-09-30 00:25:57.093872 | controller | ok
2025-09-30 00:25:57.102635 | 
2025-09-30 00:25:57.102743 | TASK [bindep : Define bindep_file fact]
2025-09-30 00:25:57.128876 | controller | skipping: Conditional result was False
2025-09-30 00:25:57.137687 | 
2025-09-30 00:25:57.137781 | TASK [bindep : Look for bindep fallback file]
2025-09-30 00:25:57.163950 | controller | skipping: Conditional result was False
2025-09-30 00:25:57.173189 | 
2025-09-30 00:25:57.173347 | TASK [bindep : Define bindep_file fact]
2025-09-30 00:25:57.200478 | controller | skipping: Conditional result was False
2025-09-30 00:25:57.208936 | 
2025-09-30 00:25:57.209088 | TASK [bindep : Include bindep tasks]
2025-09-30 00:25:57.233804 | controller | skipping: Conditional result was False
2025-09-30 00:25:57.241192 | 
2025-09-30 00:25:57.241319 | TASK [bindep : Include install tasks]
2025-09-30 00:25:57.265986 | controller | skipping: Conditional result was False
2025-09-30 00:25:57.273241 | 
2025-09-30 00:25:57.273353 | LOOP [bindep : Include package tasks]
2025-09-30 00:25:57.332559 | 
2025-09-30 00:25:57.332731 | TASK [Run test-setup role]
2025-09-30 00:25:57.352876 | controller | ok
2025-09-30 00:25:57.371420 | 
2025-09-30 00:25:57.371535 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-30 00:25:58.114635 | controller | ok
2025-09-30 00:25:58.153994 | 
2025-09-30 00:25:58.154313 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-30 00:25:58.545272 | controller | skipping: Conditional result was False
2025-09-30 00:25:58.574045 | 
2025-09-30 00:25:58.574160 | PLAY RECAP
2025-09-30 00:25:58.574203 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-30 00:25:58.574229 | 
2025-09-30 00:25:58.710126 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 00:25:58.711080 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-30 00:25:59.342886 | 
2025-09-30 00:25:59.343041 | PLAY [controller]
2025-09-30 00:25:59.364073 | 
2025-09-30 00:25:59.364218 | TASK [Create the /root directory]
2025-09-30 00:26:00.499976 | controller | ok
2025-09-30 00:26:00.507311 | 
2025-09-30 00:26:00.507468 | TASK [Install glibc-langpack-en]
2025-09-30 00:26:09.828741 | controller | ok: Nothing to do
2025-09-30 00:26:09.834667 | 
2025-09-30 00:26:09.834752 | TASK [Ensure controller directory exists]
2025-09-30 00:26:10.714785 | controller | changed
2025-09-30 00:26:10.723722 | 
2025-09-30 00:26:10.723839 | TASK [Install container runtime]
2025-09-30 00:26:10.788580 | controller | ok
2025-09-30 00:26:10.831889 | 
2025-09-30 00:26:10.832038 | LOOP [ensure-podman : Find distribution installation]
2025-09-30 00:26:10.877606 | controller | ok: "/var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-30 00:26:10.907210 | controller | included: /var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-30 00:26:10.919293 | 
2025-09-30 00:26:10.919431 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-30 00:28:33.220691 | controller | changed
2025-09-30 00:28:33.230426 | 
2025-09-30 00:28:33.230533 | TASK [ensure-podman : Fetch podman version]
2025-09-30 00:28:34.457503 | controller | Client:       Podman Engine
2025-09-30 00:28:34.457612 | controller | Version:      4.6.2
2025-09-30 00:28:34.457692 | controller | API Version:  4.6.2
2025-09-30 00:28:34.457737 | controller | Go Version:   go1.19.12
2025-09-30 00:28:34.457790 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-30 00:28:34.457833 | controller | OS/Arch:      linux/amd64
2025-09-30 00:28:35.104100 | controller | ok: Runtime: 0:00:00.348091
2025-09-30 00:28:35.111192 | 
2025-09-30 00:28:35.111303 | TASK [ensure-podman : Print podman version installed]
2025-09-30 00:28:35.140915 | Podman version: Client:       Podman Engine
2025-09-30 00:28:35.141087 | Version:      4.6.2
2025-09-30 00:28:35.141118 | API Version:  4.6.2
2025-09-30 00:28:35.141139 | Go Version:   go1.19.12
2025-09-30 00:28:35.141159 | Built:        Mon Aug 28 19:38:31 2023
2025-09-30 00:28:35.141179 | OS/Arch:      linux/amd64
2025-09-30 00:28:35.146932 | 
2025-09-30 00:28:35.147002 | TASK [ensure-podman : Validate podman engine]
2025-09-30 00:28:35.502379 | controller | skipping: Conditional result was False
2025-09-30 00:28:35.517263 | 
2025-09-30 00:28:35.517425 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-30 00:28:35.545275 | controller | skipping: Conditional result was False
2025-09-30 00:28:35.571405 | 
2025-09-30 00:28:35.571549 | TASK [Ensure python3.8 is present]
2025-09-30 00:28:35.599365 | controller | skipping: Conditional result was False
2025-09-30 00:28:35.612328 | 
2025-09-30 00:28:35.612519 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-30 00:28:35.644407 | controller | ok
2025-09-30 00:28:35.679211 | 
2025-09-30 00:28:35.679342 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-30 00:28:39.950139 | controller | ok: Nothing to do
2025-09-30 00:28:39.962465 | 
2025-09-30 00:28:39.962612 | TASK [our-ensure-python : Also install python3-devel]
2025-09-30 00:28:57.886155 | controller | changed
2025-09-30 00:28:57.913418 | 
2025-09-30 00:28:57.913628 | TASK [Run ensure-virtualenv role]
2025-09-30 00:28:57.939649 | controller | ok
2025-09-30 00:28:57.972352 | 
2025-09-30 00:28:57.972501 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-30 00:28:58.798738 | controller | /usr/bin/virtualenv
2025-09-30 00:28:59.361424 | controller | ok: Runtime: 0:00:00.006249
2025-09-30 00:28:59.370911 | 
2025-09-30 00:28:59.371086 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-30 00:28:59.398003 | controller | skipping: Conditional result was False
2025-09-30 00:28:59.398341 | controller | ok: All items complete
2025-09-30 00:28:59.398387 | 
2025-09-30 00:28:59.426556 | 
2025-09-30 00:28:59.426700 | TASK [Find the full path of the Python interpreter]
2025-09-30 00:29:00.243966 | controller | /usr/bin/python3
2025-09-30 00:29:00.798857 | controller | ok
2025-09-30 00:29:00.812792 | 
2025-09-30 00:29:00.813095 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-30 00:29:02.945785 | controller | created virtual environment CPython3.11.0.final.0-64 in 1047ms
2025-09-30 00:29:03.011254 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-30 00:29:03.011324 | 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-09-30 00:29:03.011343 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-30 00:29:03.011363 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-30 00:29:03.220673 | controller | changed
2025-09-30 00:29:03.235521 | 
2025-09-30 00:29:03.235710 | TASK [Set selinux package]
2025-09-30 00:29:03.265098 | controller | ok
2025-09-30 00:29:03.279875 | 
2025-09-30 00:29:03.280127 | TASK [Set selinux package (Fedora)]
2025-09-30 00:29:03.315834 | controller | ok
2025-09-30 00:29:03.325285 | 
2025-09-30 00:29:03.325457 | TASK [Install selinux into virtualenv]
2025-09-30 00:29:07.471640 | controller | Collecting selinux-please-lie-to-me
2025-09-30 00:29:07.606566 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-30 00:29:08.511304 | controller | Collecting setuptools<50.0.0
2025-09-30 00:29:08.524197 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-30 00:29:08.641854 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.4 MB/s eta 0:00:00
2025-09-30 00:29:08.875772 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-30 00:29:08.876116 | controller |   Attempting uninstall: setuptools
2025-09-30 00:29:08.889473 | controller |     Found existing installation: setuptools 62.6.0
2025-09-30 00:29:09.066686 | controller |     Uninstalling setuptools-62.6.0:
2025-09-30 00:29:09.097311 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-30 00:29:10.104179 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-30 00:29:10.359525 | controller |
2025-09-30 00:29:10.710257 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-30 00:29:10.710310 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-30 00:29:11.248100 | controller | ok: Runtime: 0:00:06.543740
2025-09-30 00:29:11.258117 | 
2025-09-30 00:29:11.258283 | TASK [Install pytest-forked into virtualenv]
2025-09-30 00:29:13.025628 | controller | Collecting pytest-forked
2025-09-30 00:29:13.132074 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-30 00:29:13.209664 | controller | Collecting py
2025-09-30 00:29:13.222441 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-30 00:29:13.276865 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 1.9 MB/s eta 0:00:00
2025-09-30 00:29:13.481410 | controller | Collecting pytest>=3.10
2025-09-30 00:29:13.489051 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-30 00:29:13.519474 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 14.5 MB/s eta 0:00:00
2025-09-30 00:29:13.579253 | controller | Collecting iniconfig>=1
2025-09-30 00:29:13.587392 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-30 00:29:13.669182 | controller | Collecting packaging>=20
2025-09-30 00:29:13.675109 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-30 00:29:13.689339 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.0 MB/s eta 0:00:00
2025-09-30 00:29:13.746782 | controller | Collecting pluggy<2,>=1.5
2025-09-30 00:29:13.750758 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-30 00:29:13.843352 | controller | Collecting pygments>=2.7.2
2025-09-30 00:29:13.851973 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-30 00:29:13.878083 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 54.3 MB/s eta 0:00:00
2025-09-30 00:29:14.023979 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-30 00:29:17.311921 | controller | Successfully installed iniconfig-2.1.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-09-30 00:29:17.339262 | controller |
2025-09-30 00:29:17.717665 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-30 00:29:17.717735 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-30 00:29:18.131946 | controller | ok: Runtime: 0:00:05.628530
2025-09-30 00:29:18.140950 | 
2025-09-30 00:29:18.141091 | TASK [Update pip]
2025-09-30 00:29:19.771414 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-30 00:29:20.088822 | controller | Collecting pip
2025-09-30 00:29:20.170871 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-30 00:29:20.265456 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 19.7 MB/s eta 0:00:00
2025-09-30 00:29:20.419002 | controller | Installing collected packages: pip
2025-09-30 00:29:20.419338 | controller |   Attempting uninstall: pip
2025-09-30 00:29:20.423837 | controller |     Found existing installation: pip 22.2.2
2025-09-30 00:29:20.717763 | controller |     Uninstalling pip-22.2.2:
2025-09-30 00:29:20.756579 | controller |       Successfully uninstalled pip-22.2.2
2025-09-30 00:29:23.173030 | controller | Successfully installed pip-25.2
2025-09-30 00:29:24.034139 | controller | ok: Runtime: 0:00:04.468332
2025-09-30 00:29:24.041220 | 
2025-09-30 00:29:24.041299 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-30 00:29:25.084437 | controller | changed
2025-09-30 00:29:25.092398 | 
2025-09-30 00:29:25.092494 | TASK [Install ansible into virtualenv]
2025-09-30 00:29:26.589588 | controller | Processing ./src/github.com/ansible/ansible
2025-09-30 00:29:26.600916 | controller |   Installing build dependencies: started
2025-09-30 00:29:28.899719 | controller |   Installing build dependencies: finished with status 'done'
2025-09-30 00:29:30.754946 | controller |   Getting requirements to build wheel: started
2025-09-30 00:29:30.755008 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-30 00:29:30.757419 | controller |   Preparing metadata (pyproject.toml): started
2025-09-30 00:29:31.924144 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-30 00:29:31.929460 | 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-09-30 00:29:31.935517 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-30 00:29:32.495929 | controller | ERROR
2025-09-30 00:29:32.496270 | controller | {
2025-09-30 00:29:32.496344 | controller |   "delta": "0:00:06.329563",
2025-09-30 00:29:32.496387 | controller |   "end": "2025-09-30 00:29:32.136074",
2025-09-30 00:29:32.496424 | controller |   "msg": "non-zero return code",
2025-09-30 00:29:32.496475 | controller |   "rc": 1,
2025-09-30 00:29:32.496512 | controller |   "start": "2025-09-30 00:29:25.806511"
2025-09-30 00:29:32.496546 | controller | }
failure
2025-09-30 00:29:32.499640 | 
2025-09-30 00:29:32.499757 | PLAY RECAP
2025-09-30 00:29:32.499856 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-30 00:29:32.499924 | 
2025-09-30 00:29:32.629190 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-30 00:29:32.630657 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 00:29:33.232945 | 
2025-09-30 00:29:33.233097 | PLAY [all]
2025-09-30 00:29:33.255150 | 
2025-09-30 00:29:33.255271 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-30 00:29:35.136085 | controller | changed: non-zero return code
2025-09-30 00:29:35.142334 | 
2025-09-30 00:29:35.142445 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-30 00:29:35.166742 | controller | skipping: Conditional result was False
2025-09-30 00:29:35.173218 | 
2025-09-30 00:29:35.173323 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-30 00:29:35.204043 | 
2025-09-30 00:29:35.204203 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-30 00:29:35.235073 | 
2025-09-30 00:29:35.235257 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-30 00:29:35.249532 | controller | skipping: Conditional result was False
2025-09-30 00:29:35.259611 | 
2025-09-30 00:29:35.259726 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-30 00:29:35.293696 | 
2025-09-30 00:29:35.293912 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-30 00:29:35.318877 | controller | skipping: Conditional result was False
2025-09-30 00:29:35.327942 | 
2025-09-30 00:29:35.328087 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-30 00:29:35.353751 | controller | skipping: Conditional result was False
2025-09-30 00:29:35.364304 | 
2025-09-30 00:29:35.364452 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-30 00:29:35.390566 | controller | skipping: Conditional result was False
2025-09-30 00:29:35.432077 | 
2025-09-30 00:29:35.432219 | PLAY RECAP
2025-09-30 00:29:35.432277 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-30 00:29:35.432306 | 
2025-09-30 00:29:35.543634 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 00:29:35.544861 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-30 00:29:36.174161 | 
2025-09-30 00:29:36.174292 | PLAY [all:!appliance*]
2025-09-30 00:29:36.202468 | 
2025-09-30 00:29:36.202579 | TASK [unregister the node]
2025-09-30 00:29:36.556204 | controller | skipping: Conditional result was False
2025-09-30 00:29:36.564055 | 
2025-09-30 00:29:36.564201 | TASK [include_role : fetch-output]
2025-09-30 00:29:36.599361 | controller | ok
2025-09-30 00:29:36.626625 | 
2025-09-30 00:29:36.626783 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-30 00:29:36.693363 | controller | skipping: Conditional result was False
2025-09-30 00:29:36.700037 | 
2025-09-30 00:29:36.700172 | TASK [fetch-output : Set log path for single node]
2025-09-30 00:29:36.740516 | controller | ok
2025-09-30 00:29:36.745982 | 
2025-09-30 00:29:36.746095 | LOOP [fetch-output : Ensure local output dirs]
2025-09-30 00:29:37.124803 | controller -> localhost | ok: "/var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/work/logs"
2025-09-30 00:29:37.342985 | controller -> localhost | changed: "/var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/work/artifacts"
2025-09-30 00:29:37.576450 | controller -> localhost | changed: "/var/lib/zuul/builds/309e105a6f4744f5be0752d8cff34c03/work/docs"
2025-09-30 00:29:37.595788 | 
2025-09-30 00:29:37.595940 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-30 00:29:39.869561 | controller | changed:
2025-09-30 00:29:39.869861 | controller | .d..t...... ./
2025-09-30 00:29:39.869911 | controller | cd+++++++++ controller/
2025-09-30 00:29:39.869963 | controller | changed: All items complete
2025-09-30 00:29:39.869995 | 
2025-09-30 00:29:41.946159 | controller | changed: .d..t...... ./
2025-09-30 00:29:44.046159 | controller | changed: .d..t...... ./
2025-09-30 00:29:44.071830 | 
2025-09-30 00:29:44.071998 | TASK [include_role : fetch-output-openshift]
2025-09-30 00:29:44.097555 | controller | skipping: Conditional result was False
2025-09-30 00:29:44.107480 | 
2025-09-30 00:29:44.107638 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-30 00:29:44.154406 | controller | skipping: Conditional result was False
2025-09-30 00:29:44.166136 | controller | skipping: Conditional result was False
2025-09-30 00:29:44.216986 | 
2025-09-30 00:29:44.217150 | PLAY [localhost]
2025-09-30 00:29:44.238217 | 
2025-09-30 00:29:44.238370 | TASK [Run Zuul manifest role]
2025-09-30 00:29:44.256934 | localhost | ok
2025-09-30 00:29:44.270900 | 
2025-09-30 00:29:44.271050 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-30 00:29:44.647272 | localhost | changed
2025-09-30 00:29:44.652531 | 
2025-09-30 00:29:44.652638 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-30 00:29:44.681375 | localhost | ok
2025-09-30 00:29:44.690153 | 
2025-09-30 00:29:44.690266 | TASK [Set zuul-log-path fact]
2025-09-30 00:29:44.709359 | localhost | ok
2025-09-30 00:29:44.749820 | 
2025-09-30 00:29:44.749946 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 00:29:44.788589 | localhost | ok
2025-09-30 00:29:44.797325 | 
2025-09-30 00:29:44.797449 | LOOP [Run upload-logs-swift role]
2025-09-30 00:29:44.832533 | localhost | Output suppressed because no_log was given
2025-09-30 00:29:44.858890 | 
2025-09-30 00:29:44.859056 | TASK [Set zuul-log-path fact]
2025-09-30 00:29:44.883702 | localhost | skipping: Conditional result was False
2025-09-30 00:29:44.896548 | 
2025-09-30 00:29:44.896743 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-30 00:29:45.272564 | localhost -> localhost | ok: Runtime: 0:00:00.009482
2025-09-30 00:29:45.278458 | 
2025-09-30 00:29:45.278557 | TASK [upload-logs-swift : Upload logs to swift]