2026-01-17 00:14:23.590222 | Job console starting...
2026-01-17 00:14:23.604833 | Updating repositories
2026-01-17 00:14:23.762561 | Preparing job workspace
2026-01-17 00:14:27.769125 | Running Ansible setup...
2026-01-17 00:14:32.643461 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-17 00:14:33.275700 | 
2026-01-17 00:14:33.275842 | PLAY [localhost]
2026-01-17 00:14:33.285198 | 
2026-01-17 00:14:33.285303 | TASK [Gathering Facts]
2026-01-17 00:14:34.342305 | localhost | ok
2026-01-17 00:14:34.372096 | 
2026-01-17 00:14:34.372259 | TASK [Setup log path fact]
2026-01-17 00:14:34.396203 | localhost | ok
2026-01-17 00:14:34.413665 | 
2026-01-17 00:14:34.413794 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-17 00:14:34.454985 | localhost | ok
2026-01-17 00:14:34.465544 | 
2026-01-17 00:14:34.465642 | TASK [emit-job-header : Print job information]
2026-01-17 00:14:34.516635 | # Job Information
2026-01-17 00:14:34.516898 | Ansible Version: 2.15.12
2026-01-17 00:14:34.516950 | Job: ansible-test-sanity-docker-milestone
2026-01-17 00:14:34.516980 | Pipeline: periodic
2026-01-17 00:14:34.517005 | Executor: ze01.softwarefactory-project.io
2026-01-17 00:14:34.517063 | Triggered by: https://github.com/ansible-collections/ansible.network
2026-01-17 00:14:34.517094 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/485/ansible/485f1e0d1e6b42bdab744880648b416f/
2026-01-17 00:14:34.517122 | Event ID: 1d1f0d08e7134262830bd5487e0cab0e
2026-01-17 00:14:34.522287 | 
2026-01-17 00:14:34.522376 | LOOP [emit-job-header : Print node information]
2026-01-17 00:14:34.644413 | localhost | ok:
2026-01-17 00:14:34.644664 | localhost | # Node Information
2026-01-17 00:14:34.644720 | localhost | Inventory Hostname: controller
2026-01-17 00:14:34.644763 | localhost | Hostname: np0005586318
2026-01-17 00:14:34.644805 | localhost | Username: zuul
2026-01-17 00:14:34.644851 | localhost | Distro: Fedora 37
2026-01-17 00:14:34.644891 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2026-01-17 00:14:34.644928 | localhost | Region: ca-ymq-1
2026-01-17 00:14:34.644964 | localhost | Label: ansible-fedora-37-1vcpu
2026-01-17 00:14:34.645000 | localhost | Product Name: OpenStack Nova
2026-01-17 00:14:34.645072 | localhost | Interface IP: 199.204.45.115
2026-01-17 00:14:34.670948 | 
2026-01-17 00:14:34.671216 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-01-17 00:14:35.118569 | localhost -> localhost | changed
2026-01-17 00:14:35.130934 | 
2026-01-17 00:14:35.131114 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-01-17 00:14:36.075253 | localhost -> localhost | changed
2026-01-17 00:14:36.121924 | 
2026-01-17 00:14:36.122100 | PLAY [all:!appliance*]
2026-01-17 00:14:36.149453 | 
2026-01-17 00:14:36.149778 | TASK [include_role : start-zuul-console]
2026-01-17 00:14:36.173331 | controller | ok
2026-01-17 00:14:36.197840 | 
2026-01-17 00:14:36.197967 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-01-17 00:14:36.574090 | controller | ok
2026-01-17 00:14:36.601424 | 
2026-01-17 00:14:36.601602 | TASK [use-our-mirror : Retrieve the IP address]
2026-01-17 00:15:37.783557 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2026-01-17 00:15:37.798838 | 
2026-01-17 00:15:37.799011 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2026-01-17 00:15:38.379437 | controller | skipping: Conditional result was False
2026-01-17 00:15:38.393732 | 
2026-01-17 00:15:38.393905 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2026-01-17 00:15:38.419811 | controller | skipping: Conditional result was False
2026-01-17 00:15:38.426262 | 
2026-01-17 00:15:38.426364 | TASK [use-our-mirror : Create the podman configuration directory]
2026-01-17 00:15:38.450496 | controller | skipping: Conditional result was False
2026-01-17 00:15:38.456723 | 
2026-01-17 00:15:38.456817 | TASK [use-our-mirror : Copy the podman configuration]
2026-01-17 00:15:38.480972 | controller | skipping: Conditional result was False
2026-01-17 00:15:38.487755 | 
2026-01-17 00:15:38.487828 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2026-01-17 00:15:38.512065 | controller | skipping: Conditional result was False
2026-01-17 00:15:38.518768 | 
2026-01-17 00:15:38.518863 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2026-01-17 00:15:38.533189 | controller | skipping: Conditional result was False
2026-01-17 00:15:38.546587 | 
2026-01-17 00:15:38.546714 | TASK [Disable Fedora Modular]
2026-01-17 00:15:38.781182 | controller | changed
2026-01-17 00:15:38.788262 | 
2026-01-17 00:15:38.788366 | TASK [Enable EPEL]
2026-01-17 00:15:38.823462 | controller | skipping: Conditional result was False
2026-01-17 00:15:38.830685 | 
2026-01-17 00:15:38.830819 | TASK [Register the RHEL node]
2026-01-17 00:15:39.385227 | 
2026-01-17 00:15:39.385453 | TASK [Show the subscription-manager status]
2026-01-17 00:15:39.920218 | controller | skipping: Conditional result was False
2026-01-17 00:15:39.927439 | 
2026-01-17 00:15:39.927539 | TASK [Enable EPEL on RHEL]
2026-01-17 00:15:40.464281 | controller | skipping: Conditional result was False
2026-01-17 00:15:40.478089 | 
2026-01-17 00:15:40.478277 | TASK [Install git and tox]
2026-01-17 00:16:24.516291 | controller | changed
2026-01-17 00:16:24.530892 | 
2026-01-17 00:16:24.531125 | TASK [include_role : prepare-workspace]
2026-01-17 00:16:24.562295 | controller | ok
2026-01-17 00:16:24.598587 | 
2026-01-17 00:16:24.598759 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-01-17 00:16:24.849624 | controller | ok
2026-01-17 00:16:24.863760 | 
2026-01-17 00:16:24.863900 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-01-17 00:16:37.809368 | controller | Output suppressed because no_log was given
2026-01-17 00:16:37.854361 | 
2026-01-17 00:16:37.854522 | TASK [include_role : prepare-workspace-openshift]
2026-01-17 00:16:37.874176 | controller | skipping: Conditional result was False
2026-01-17 00:16:37.903324 | 
2026-01-17 00:16:37.903431 | PLAY [all:!appliance]
2026-01-17 00:16:37.926549 | 
2026-01-17 00:16:37.926668 | TASK [Run add-build-sshkey role (RSA)]
2026-01-17 00:16:37.990244 | controller | ok
2026-01-17 00:16:38.009344 | 
2026-01-17 00:16:38.009569 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-17 00:16:38.272615 | controller -> localhost | ok
2026-01-17 00:16:38.278995 | 
2026-01-17 00:16:38.279080 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-17 00:16:38.299744 | controller | ok
2026-01-17 00:16:38.315807 | controller | included: /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-17 00:16:38.322261 | 
2026-01-17 00:16:38.322326 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-17 00:16:38.814847 | controller -> localhost | Generating public/private rsa key pair.
2026-01-17 00:16:38.815074 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/work/485f1e0d1e6b42bdab744880648b416f_id_rsa.
2026-01-17 00:16:38.815119 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/work/485f1e0d1e6b42bdab744880648b416f_id_rsa.pub.
2026-01-17 00:16:38.815143 | controller -> localhost | The key fingerprint is:
2026-01-17 00:16:38.815162 | controller -> localhost | SHA256:2hyMqK9ZIfcvoExXIa+J0KJ7Rz7UhIwWjOCTHQMHBEY zuul-build-sshkey
2026-01-17 00:16:38.815182 | controller -> localhost | The key's randomart image is:
2026-01-17 00:16:38.815200 | controller -> localhost | +---[RSA 2048]----+
2026-01-17 00:16:38.815217 | controller -> localhost | |BEo+             |
2026-01-17 00:16:38.815237 | controller -> localhost | |+ * + .          |
2026-01-17 00:16:38.815256 | controller -> localhost | | = = + .         |
2026-01-17 00:16:38.815274 | controller -> localhost | |o = o.+o         |
2026-01-17 00:16:38.815292 | controller -> localhost | |.+..+*. S        |
2026-01-17 00:16:38.815323 | controller -> localhost | |. o+Bo.+ .       |
2026-01-17 00:16:38.815346 | controller -> localhost | | +.*..o o        |
2026-01-17 00:16:38.815367 | controller -> localhost | |. +++ ..         |
2026-01-17 00:16:38.815386 | controller -> localhost | | .oo.. ..        |
2026-01-17 00:16:38.815406 | controller -> localhost | +----[SHA256]-----+
2026-01-17 00:16:38.815455 | controller -> localhost | ok: Runtime: 0:00:00.123093
2026-01-17 00:16:38.823423 | 
2026-01-17 00:16:38.823514 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-17 00:16:38.854895 | controller | ok
2026-01-17 00:16:38.866610 | controller | included: /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-17 00:16:38.877336 | 
2026-01-17 00:16:38.877449 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-17 00:16:38.902641 | controller | skipping: Conditional result was False
2026-01-17 00:16:38.909449 | 
2026-01-17 00:16:38.909529 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-17 00:16:39.365774 | controller | changed
2026-01-17 00:16:39.381847 | 
2026-01-17 00:16:39.382092 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-17 00:16:39.618807 | controller | ok
2026-01-17 00:16:39.637939 | 
2026-01-17 00:16:39.638164 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-17 00:16:40.268784 | controller | changed
2026-01-17 00:16:40.275571 | 
2026-01-17 00:16:40.275710 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-17 00:16:40.922562 | controller | changed
2026-01-17 00:16:40.940178 | 
2026-01-17 00:16:40.940351 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-17 00:16:40.966592 | controller | skipping: Conditional result was False
2026-01-17 00:16:40.988347 | 
2026-01-17 00:16:40.988504 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-17 00:16:41.350915 | controller -> localhost | changed
2026-01-17 00:16:41.377284 | 
2026-01-17 00:16:41.377526 | TASK [add-build-sshkey : Add back temp key]
2026-01-17 00:16:41.669183 | controller -> localhost | Identity added: /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/work/485f1e0d1e6b42bdab744880648b416f_id_rsa (zuul-build-sshkey)
2026-01-17 00:16:41.669417 | controller -> localhost | ok: Runtime: 0:00:00.012844
2026-01-17 00:16:41.675973 | 
2026-01-17 00:16:41.676055 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-17 00:16:42.012399 | controller | ok
2026-01-17 00:16:42.026072 | 
2026-01-17 00:16:42.026286 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-17 00:16:42.063777 | controller | skipping: Conditional result was False
2026-01-17 00:16:42.089412 | 
2026-01-17 00:16:42.089602 | TASK [Run add-build-sshkey role (ECDSA)]
2026-01-17 00:16:42.128226 | controller | ok
2026-01-17 00:16:42.159721 | 
2026-01-17 00:16:42.159858 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-17 00:16:42.418734 | controller -> localhost | ok
2026-01-17 00:16:42.427820 | 
2026-01-17 00:16:42.427929 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-17 00:16:42.448601 | controller | ok
2026-01-17 00:16:42.459883 | controller | included: /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-17 00:16:42.465971 | 
2026-01-17 00:16:42.466051 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-17 00:16:42.772843 | controller -> localhost | Generating public/private ecdsa key pair.
2026-01-17 00:16:42.773225 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/work/485f1e0d1e6b42bdab744880648b416f_id_ecdsa.
2026-01-17 00:16:42.773298 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/work/485f1e0d1e6b42bdab744880648b416f_id_ecdsa.pub.
2026-01-17 00:16:42.773387 | controller -> localhost | The key fingerprint is:
2026-01-17 00:16:42.773459 | controller -> localhost | SHA256:emqJ+GNlPF01OI/g5KBIV8P8GRQwLYrZMdidcA19f7Q zuul-build-sshkey
2026-01-17 00:16:42.773523 | controller -> localhost | The key's randomart image is:
2026-01-17 00:16:42.773580 | controller -> localhost | +---[ECDSA 521]---+
2026-01-17 00:16:42.773629 | controller -> localhost | |   o.*BOo. .     |
2026-01-17 00:16:42.773692 | controller -> localhost | |  o =.BoB + o .  |
2026-01-17 00:16:42.773757 | controller -> localhost | | . * = B = * o . |
2026-01-17 00:16:42.773818 | controller -> localhost | |  + +   = o o E  |
2026-01-17 00:16:42.773875 | controller -> localhost | |     . .S.   .   |
2026-01-17 00:16:42.773936 | controller -> localhost | |      =..        |
2026-01-17 00:16:42.773987 | controller -> localhost | |   . +.o.        |
2026-01-17 00:16:42.774094 | controller -> localhost | |  . + oo         |
2026-01-17 00:16:42.774161 | controller -> localhost | |   o.o.          |
2026-01-17 00:16:42.774220 | controller -> localhost | +----[SHA256]-----+
2026-01-17 00:16:42.774356 | controller -> localhost | ok: Runtime: 0:00:00.014832
2026-01-17 00:16:42.792818 | 
2026-01-17 00:16:42.792974 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-17 00:16:42.828049 | controller | ok
2026-01-17 00:16:42.838130 | controller | included: /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-17 00:16:42.850412 | 
2026-01-17 00:16:42.850506 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-17 00:16:42.865658 | controller | skipping: Conditional result was False
2026-01-17 00:16:42.873128 | 
2026-01-17 00:16:42.873248 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-17 00:16:43.144843 | controller | changed
2026-01-17 00:16:43.153811 | 
2026-01-17 00:16:43.153906 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-17 00:16:43.374788 | controller | ok
2026-01-17 00:16:43.388092 | 
2026-01-17 00:16:43.388233 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-17 00:16:43.995289 | controller | changed
2026-01-17 00:16:44.004909 | 
2026-01-17 00:16:44.005072 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-17 00:16:44.631815 | controller | changed
2026-01-17 00:16:44.639965 | 
2026-01-17 00:16:44.640161 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-17 00:16:44.666074 | controller | skipping: Conditional result was False
2026-01-17 00:16:44.675075 | 
2026-01-17 00:16:44.675212 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-17 00:16:44.955905 | controller -> localhost | changed
2026-01-17 00:16:44.970104 | 
2026-01-17 00:16:44.970225 | TASK [add-build-sshkey : Add back temp key]
2026-01-17 00:16:45.260262 | controller -> localhost | Identity added: /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/work/485f1e0d1e6b42bdab744880648b416f_id_ecdsa (zuul-build-sshkey)
2026-01-17 00:16:45.260569 | controller -> localhost | ok: Runtime: 0:00:00.013937
2026-01-17 00:16:45.269191 | 
2026-01-17 00:16:45.269330 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-17 00:16:45.521621 | controller | ok
2026-01-17 00:16:45.536229 | 
2026-01-17 00:16:45.536430 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-17 00:16:45.563940 | controller | skipping: Conditional result was False
2026-01-17 00:16:45.591981 | 
2026-01-17 00:16:45.592209 | TASK [include_role : remove-zuul-sshkey]
2026-01-17 00:16:45.608379 | controller | skipping: Conditional result was False
2026-01-17 00:16:45.662469 | 
2026-01-17 00:16:45.662623 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-01-17 00:16:45.885469 | controller | ok: "logs"
2026-01-17 00:16:45.885736 | controller | ok: All items complete
2026-01-17 00:16:45.885764 | 
2026-01-17 00:16:46.084555 | controller | ok: "artifacts"
2026-01-17 00:16:46.275051 | controller | ok: "docs"
2026-01-17 00:16:46.288093 | 
2026-01-17 00:16:46.288249 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-01-17 00:16:46.518569 | controller | changed: "logs"
2026-01-17 00:16:46.742728 | controller | changed: "artifacts"
2026-01-17 00:16:46.992068 | controller | changed: "docs"
2026-01-17 00:16:47.041771 | 
2026-01-17 00:16:47.041913 | PLAY RECAP
2026-01-17 00:16:47.041973 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2026-01-17 00:16:47.042009 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-01-17 00:16:47.042060 | 
2026-01-17 00:16:47.173001 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-17 00:16:47.173919 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-17 00:16:47.754825 | 
2026-01-17 00:16:47.754964 | PLAY [all]
2026-01-17 00:16:47.777886 | 
2026-01-17 00:16:47.778050 | TASK [Install binary dependencies]
2026-01-17 00:16:47.829505 | controller | ok
2026-01-17 00:16:47.850822 | 
2026-01-17 00:16:47.850963 | TASK [bindep : Include find tasks]
2026-01-17 00:16:47.882409 | controller | ok
2026-01-17 00:16:47.891257 | controller | included: /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2026-01-17 00:16:47.898719 | 
2026-01-17 00:16:47.898811 | TASK [bindep : Look for bindep.txt]
2026-01-17 00:16:48.255769 | controller | ok
2026-01-17 00:16:48.261915 | 
2026-01-17 00:16:48.262002 | TASK [bindep : Define bindep_file fact]
2026-01-17 00:16:48.276227 | controller | skipping: Conditional result was False
2026-01-17 00:16:48.285327 | 
2026-01-17 00:16:48.285458 | TASK [bindep : Look for other-requirements.txt]
2026-01-17 00:16:48.501009 | controller | ok
2026-01-17 00:16:48.518753 | 
2026-01-17 00:16:48.518982 | TASK [bindep : Define bindep_file fact]
2026-01-17 00:16:48.546873 | controller | skipping: Conditional result was False
2026-01-17 00:16:48.557042 | 
2026-01-17 00:16:48.557157 | TASK [bindep : Look for bindep fallback file]
2026-01-17 00:16:48.582488 | controller | skipping: Conditional result was False
2026-01-17 00:16:48.592885 | 
2026-01-17 00:16:48.593044 | TASK [bindep : Define bindep_file fact]
2026-01-17 00:16:48.618086 | controller | skipping: Conditional result was False
2026-01-17 00:16:48.626826 | 
2026-01-17 00:16:48.626930 | TASK [bindep : Include bindep tasks]
2026-01-17 00:16:48.653127 | controller | skipping: Conditional result was False
2026-01-17 00:16:48.660763 | 
2026-01-17 00:16:48.660888 | TASK [bindep : Include install tasks]
2026-01-17 00:16:48.686293 | controller | skipping: Conditional result was False
2026-01-17 00:16:48.692593 | 
2026-01-17 00:16:48.692663 | LOOP [bindep : Include package tasks]
2026-01-17 00:16:48.748844 | 
2026-01-17 00:16:48.749011 | TASK [Run test-setup role]
2026-01-17 00:16:48.770708 | controller | ok
2026-01-17 00:16:48.787731 | 
2026-01-17 00:16:48.787822 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2026-01-17 00:16:49.001368 | controller | ok
2026-01-17 00:16:49.007775 | 
2026-01-17 00:16:49.007855 | TASK [test-setup : Run tools/test-setup.sh]
2026-01-17 00:16:49.543209 | controller | skipping: Conditional result was False
2026-01-17 00:16:49.586242 | 
2026-01-17 00:16:49.586397 | PLAY RECAP
2026-01-17 00:16:49.586478 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-17 00:16:49.586522 | 
2026-01-17 00:16:49.706732 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-17 00:16:49.707924 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-17 00:16:50.297092 | 
2026-01-17 00:16:50.297234 | PLAY [controller]
2026-01-17 00:16:50.319663 | 
2026-01-17 00:16:50.319804 | TASK [Create the /root directory]
2026-01-17 00:16:50.735994 | controller | ok
2026-01-17 00:16:50.746837 | 
2026-01-17 00:16:50.746969 | TASK [Install glibc-langpack-en]
2026-01-17 00:16:54.663222 | controller | ok: Nothing to do
2026-01-17 00:16:54.671912 | 
2026-01-17 00:16:54.672006 | TASK [Ensure controller directory exists]
2026-01-17 00:16:54.900550 | controller | changed
2026-01-17 00:16:54.910377 | 
2026-01-17 00:16:54.910506 | TASK [Install container runtime]
2026-01-17 00:16:54.985564 | controller | ok
2026-01-17 00:16:55.036792 | 
2026-01-17 00:16:55.036941 | LOOP [ensure-podman : Find distribution installation]
2026-01-17 00:16:55.061520 | controller | ok: "/var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2026-01-17 00:16:55.068293 | controller | included: /var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2026-01-17 00:16:55.074722 | 
2026-01-17 00:16:55.074791 | TASK [ensure-podman : Install podman (RedHat)]
2026-01-17 00:18:01.396886 | controller | changed
2026-01-17 00:18:01.411127 | 
2026-01-17 00:18:01.411319 | TASK [ensure-podman : Fetch podman version]
2026-01-17 00:18:01.991265 | controller | Client:       Podman Engine
2026-01-17 00:18:02.025177 | controller | Version:      4.6.2
2026-01-17 00:18:02.025223 | controller | API Version:  4.6.2
2026-01-17 00:18:02.025229 | controller | Go Version:   go1.19.12
2026-01-17 00:18:02.025244 | controller | Built:        Mon Aug 28 19:38:31 2023
2026-01-17 00:18:02.025251 | controller | OS/Arch:      linux/amd64
2026-01-17 00:18:02.462200 | controller | ok: Runtime: 0:00:00.203810
2026-01-17 00:18:02.478997 | 
2026-01-17 00:18:02.479220 | TASK [ensure-podman : Print podman version installed]
2026-01-17 00:18:02.511971 | Podman version: Client:       Podman Engine
2026-01-17 00:18:02.512263 | Version:      4.6.2
2026-01-17 00:18:02.512327 | API Version:  4.6.2
2026-01-17 00:18:02.512374 | Go Version:   go1.19.12
2026-01-17 00:18:02.512415 | Built:        Mon Aug 28 19:38:31 2023
2026-01-17 00:18:02.512455 | OS/Arch:      linux/amd64
2026-01-17 00:18:02.526855 | 
2026-01-17 00:18:02.527047 | TASK [ensure-podman : Validate podman engine]
2026-01-17 00:18:03.072886 | controller | skipping: Conditional result was False
2026-01-17 00:18:03.087544 | 
2026-01-17 00:18:03.087697 | TASK [ensure-podman : Set up docker compatability socket]
2026-01-17 00:18:03.115881 | controller | skipping: Conditional result was False
2026-01-17 00:18:03.145252 | 
2026-01-17 00:18:03.145456 | TASK [Ensure python3.8 is present]
2026-01-17 00:18:03.173442 | controller | skipping: Conditional result was False
2026-01-17 00:18:03.182662 | 
2026-01-17 00:18:03.182883 | TASK [Run our-ensure-python role (Fedora only for now)]
2026-01-17 00:18:03.206691 | controller | ok
2026-01-17 00:18:03.234548 | 
2026-01-17 00:18:03.234684 | TASK [our-ensure-python : Install the right Python version (rpm)]
2026-01-17 00:18:04.641968 | controller | ok: Nothing to do
2026-01-17 00:18:04.657346 | 
2026-01-17 00:18:04.657523 | TASK [our-ensure-python : Also install python3-devel]
2026-01-17 00:18:14.010902 | controller | changed
2026-01-17 00:18:14.024792 | 
2026-01-17 00:18:14.024928 | TASK [Run ensure-virtualenv role]
2026-01-17 00:18:14.055974 | controller | ok
2026-01-17 00:18:14.077129 | 
2026-01-17 00:18:14.077244 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2026-01-17 00:18:14.338982 | controller | /usr/bin/virtualenv
2026-01-17 00:18:14.648981 | controller | ok: Runtime: 0:00:00.005390
2026-01-17 00:18:14.664884 | 
2026-01-17 00:18:14.665119 | LOOP [ensure-virtualenv : Install virtualenv package]
2026-01-17 00:18:14.702424 | controller | skipping: Conditional result was False
2026-01-17 00:18:14.702884 | controller | ok: All items complete
2026-01-17 00:18:14.702946 | 
2026-01-17 00:18:14.743178 | 
2026-01-17 00:18:14.743402 | TASK [Find the full path of the Python interpreter]
2026-01-17 00:18:14.974041 | controller | /usr/bin/python3
2026-01-17 00:18:15.292481 | controller | ok
2026-01-17 00:18:15.306847 | 
2026-01-17 00:18:15.307009 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2026-01-17 00:18:16.270561 | controller | created virtual environment CPython3.11.0.final.0-64 in 511ms
2026-01-17 00:18:16.297189 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2026-01-17 00:18:16.297213 | 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)
2026-01-17 00:18:16.297226 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2026-01-17 00:18:16.297242 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2026-01-17 00:18:16.369886 | controller | changed
2026-01-17 00:18:16.389741 | 
2026-01-17 00:18:16.389970 | TASK [Set selinux package]
2026-01-17 00:18:16.431563 | controller | ok
2026-01-17 00:18:16.444059 | 
2026-01-17 00:18:16.444269 | TASK [Set selinux package (Fedora)]
2026-01-17 00:18:16.492456 | controller | ok
2026-01-17 00:18:16.501738 | 
2026-01-17 00:18:16.501838 | TASK [Install selinux into virtualenv]
2026-01-17 00:18:41.943480 | controller | Collecting selinux-please-lie-to-me
2026-01-17 00:18:54.219800 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2026-01-17 00:18:54.529805 | controller | Collecting setuptools<50.0.0
2026-01-17 00:18:54.538981 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2026-01-17 00:18:54.603476 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 14.2 MB/s eta 0:00:00
2026-01-17 00:18:54.687258 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2026-01-17 00:18:54.687370 | controller |   Attempting uninstall: setuptools
2026-01-17 00:18:54.689803 | controller |     Found existing installation: setuptools 62.6.0
2026-01-17 00:18:54.752498 | controller |     Uninstalling setuptools-62.6.0:
2026-01-17 00:18:54.760820 | controller |       Successfully uninstalled setuptools-62.6.0
2026-01-17 00:18:55.107886 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2026-01-17 00:19:11.378011 | controller |
2026-01-17 00:19:11.461987 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-17 00:19:11.462041 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-17 00:19:11.579311 | controller | ok: Runtime: 0:00:54.754033
2026-01-17 00:19:11.591897 | 
2026-01-17 00:19:11.592166 | TASK [Install pytest-forked into virtualenv]
2026-01-17 00:19:24.522697 | controller | Collecting pytest-forked
2026-01-17 00:19:36.831676 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2026-01-17 00:19:36.892428 | controller | Collecting py
2026-01-17 00:19:36.899747 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2026-01-17 00:19:36.919536 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.4 MB/s eta 0:00:00
2026-01-17 00:19:37.038789 | controller | Collecting pytest>=3.10
2026-01-17 00:19:37.043986 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2026-01-17 00:19:37.067385 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 19.8 MB/s eta 0:00:00
2026-01-17 00:19:37.109168 | controller | Collecting iniconfig>=1.0.1
2026-01-17 00:19:37.112562 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2026-01-17 00:19:37.154585 | controller | Collecting packaging>=22
2026-01-17 00:19:37.157921 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2026-01-17 00:19:37.162817 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 21.0 MB/s eta 0:00:00
2026-01-17 00:19:37.198135 | controller | Collecting pluggy<2,>=1.5
2026-01-17 00:19:37.201343 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2026-01-17 00:19:37.248116 | controller | Collecting pygments>=2.7.2
2026-01-17 00:19:37.254350 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2026-01-17 00:19:37.293824 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 33.4 MB/s eta 0:00:00
2026-01-17 00:19:37.363398 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2026-01-17 00:19:38.413450 | 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
2026-01-17 00:19:38.422163 | controller |
2026-01-17 00:19:38.488140 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-17 00:19:38.488184 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-17 00:19:38.661812 | controller | ok: Runtime: 0:00:26.655263
2026-01-17 00:19:38.668209 | 
2026-01-17 00:19:38.668285 | TASK [Update pip]
2026-01-17 00:19:39.162573 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2026-01-17 00:19:49.221197 | controller | Collecting pip
2026-01-17 00:20:01.413411 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2026-01-17 00:20:01.477154 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 30.7 MB/s eta 0:00:00
2026-01-17 00:20:01.543270 | controller | Installing collected packages: pip
2026-01-17 00:20:01.543413 | controller |   Attempting uninstall: pip
2026-01-17 00:20:01.545805 | controller |     Found existing installation: pip 22.2.2
2026-01-17 00:20:01.691012 | controller |     Uninstalling pip-22.2.2:
2026-01-17 00:20:01.708397 | controller |       Successfully uninstalled pip-22.2.2
2026-01-17 00:20:02.520589 | controller | Successfully installed pip-25.3
2026-01-17 00:20:02.712541 | controller | ok: Runtime: 0:00:23.729514
2026-01-17 00:20:02.722874 | 
2026-01-17 00:20:02.722972 | TASK [Ensure pip temp directory exists in /var/tmp]
2026-01-17 00:20:02.950313 | controller | changed
2026-01-17 00:20:02.957328 | 
2026-01-17 00:20:02.957396 | TASK [Install ansible into virtualenv]
2026-01-17 00:20:03.446512 | controller | Processing ./src/github.com/ansible/ansible
2026-01-17 00:20:03.449901 | controller |   Installing build dependencies: started
2026-01-17 00:20:24.337701 | controller |   Installing build dependencies: finished with status 'done'
2026-01-17 00:20:24.338850 | controller |   Getting requirements to build wheel: started
2026-01-17 00:20:25.079891 | controller |   Getting requirements to build wheel: finished with status 'done'
2026-01-17 00:20:25.080777 | controller |   Preparing metadata (pyproject.toml): started
2026-01-17 00:20:25.561505 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2026-01-17 00:20:25.564199 | 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.
2026-01-17 00:20:25.566837 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2026-01-17 00:20:26.003031 | controller | ERROR
2026-01-17 00:20:26.003247 | controller | {
2026-01-17 00:20:26.003278 | controller |   "delta": "0:00:22.453999",
2026-01-17 00:20:26.003297 | controller |   "end": "2026-01-17 00:20:25.625170",
2026-01-17 00:20:26.003314 | controller |   "msg": "non-zero return code",
2026-01-17 00:20:26.003346 | controller |   "rc": 1,
2026-01-17 00:20:26.003363 | controller |   "start": "2026-01-17 00:20:03.171171"
2026-01-17 00:20:26.003380 | controller | }
failure
2026-01-17 00:20:26.004988 | 
2026-01-17 00:20:26.005063 | PLAY RECAP
2026-01-17 00:20:26.005121 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2026-01-17 00:20:26.005151 | 
2026-01-17 00:20:26.120986 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-17 00:20:26.122460 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-17 00:20:26.729786 | 
2026-01-17 00:20:26.729901 | PLAY [all]
2026-01-17 00:20:26.751464 | 
2026-01-17 00:20:26.751576 | TASK [fetch-subunit-output : Find stestr or testr executable]
2026-01-17 00:20:27.041576 | controller | changed: non-zero return code
2026-01-17 00:20:27.056151 | 
2026-01-17 00:20:27.056408 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2026-01-17 00:20:27.084577 | controller | skipping: Conditional result was False
2026-01-17 00:20:27.094159 | 
2026-01-17 00:20:27.094277 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2026-01-17 00:20:27.126930 | 
2026-01-17 00:20:27.127110 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2026-01-17 00:20:27.158341 | 
2026-01-17 00:20:27.158509 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2026-01-17 00:20:27.183074 | controller | skipping: Conditional result was False
2026-01-17 00:20:27.191238 | 
2026-01-17 00:20:27.191329 | LOOP [fetch-subunit-output : Generate subunit file]
2026-01-17 00:20:27.222245 | 
2026-01-17 00:20:27.222409 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2026-01-17 00:20:27.246637 | controller | skipping: Conditional result was False
2026-01-17 00:20:27.253444 | 
2026-01-17 00:20:27.253535 | TASK [fetch-subunit-output : Remove the temporary file]
2026-01-17 00:20:27.278516 | controller | skipping: Conditional result was False
2026-01-17 00:20:27.287432 | 
2026-01-17 00:20:27.287536 | TASK [fetch-subunit-output : Process and fetch subunit results]
2026-01-17 00:20:27.312559 | controller | skipping: Conditional result was False
2026-01-17 00:20:27.340729 | 
2026-01-17 00:20:27.340828 | PLAY RECAP
2026-01-17 00:20:27.340868 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-17 00:20:27.340888 | 
2026-01-17 00:20:27.446235 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-17 00:20:27.447174 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2026-01-17 00:20:28.073352 | 
2026-01-17 00:20:28.073605 | PLAY [all:!appliance*]
2026-01-17 00:20:28.096392 | 
2026-01-17 00:20:28.096531 | TASK [unregister the node]
2026-01-17 00:20:28.631640 | controller | skipping: Conditional result was False
2026-01-17 00:20:28.637326 | 
2026-01-17 00:20:28.637402 | TASK [include_role : fetch-output]
2026-01-17 00:20:28.666774 | controller | ok
2026-01-17 00:20:28.685800 | 
2026-01-17 00:20:28.685873 | TASK [fetch-output : Set log path for multiple nodes]
2026-01-17 00:20:28.750610 | controller | skipping: Conditional result was False
2026-01-17 00:20:28.757009 | 
2026-01-17 00:20:28.757093 | TASK [fetch-output : Set log path for single node]
2026-01-17 00:20:28.800003 | controller | ok
2026-01-17 00:20:28.808674 | 
2026-01-17 00:20:28.808762 | LOOP [fetch-output : Ensure local output dirs]
2026-01-17 00:20:29.265147 | controller -> localhost | ok: "/var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/work/logs"
2026-01-17 00:20:29.521830 | controller -> localhost | changed: "/var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/work/artifacts"
2026-01-17 00:20:29.781988 | controller -> localhost | changed: "/var/lib/zuul/builds/485f1e0d1e6b42bdab744880648b416f/work/docs"
2026-01-17 00:20:29.795811 | 
2026-01-17 00:20:29.795978 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-01-17 00:20:30.549240 | controller | changed:
2026-01-17 00:20:30.549863 | controller | .d..t...... ./
2026-01-17 00:20:30.549936 | controller | cd+++++++++ controller/
2026-01-17 00:20:30.550078 | controller | changed: All items complete
2026-01-17 00:20:30.550135 | 
2026-01-17 00:20:31.063823 | controller | changed: .d..t...... ./
2026-01-17 00:20:31.607128 | controller | changed: .d..t...... ./
2026-01-17 00:20:31.651485 | 
2026-01-17 00:20:31.651688 | TASK [include_role : fetch-output-openshift]
2026-01-17 00:20:31.668430 | controller | skipping: Conditional result was False
2026-01-17 00:20:31.682496 | 
2026-01-17 00:20:31.682685 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-01-17 00:20:31.710886 | controller | skipping: Conditional result was False
2026-01-17 00:20:31.720795 | controller | skipping: Conditional result was False
2026-01-17 00:20:31.760344 | 
2026-01-17 00:20:31.760512 | PLAY [localhost]
2026-01-17 00:20:31.772847 | 
2026-01-17 00:20:31.773207 | TASK [Run Zuul manifest role]
2026-01-17 00:20:31.791668 | localhost | ok
2026-01-17 00:20:31.807918 | 
2026-01-17 00:20:31.808105 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-01-17 00:20:32.224343 | localhost | changed
2026-01-17 00:20:32.229414 | 
2026-01-17 00:20:32.229493 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-01-17 00:20:32.259100 | localhost | ok
2026-01-17 00:20:32.267076 | 
2026-01-17 00:20:32.267144 | TASK [Set zuul-log-path fact]
2026-01-17 00:20:32.285402 | localhost | ok
2026-01-17 00:20:32.300153 | 
2026-01-17 00:20:32.300244 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-17 00:20:32.328825 | localhost | ok
2026-01-17 00:20:32.337581 | 
2026-01-17 00:20:32.337676 | LOOP [Run upload-logs-swift role]
2026-01-17 00:20:32.372494 | localhost | Output suppressed because no_log was given
2026-01-17 00:20:32.402307 | 
2026-01-17 00:20:32.402486 | TASK [Set zuul-log-path fact]
2026-01-17 00:20:32.427499 | localhost | skipping: Conditional result was False
2026-01-17 00:20:32.433144 | 
2026-01-17 00:20:32.433247 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2026-01-17 00:20:32.857958 | localhost -> localhost | ok: Runtime: 0:00:00.007384
2026-01-17 00:20:32.913315 | 
2026-01-17 00:20:32.913613 | TASK [upload-logs-swift : Upload logs to swift]