2025-12-09 00:31:00.606651 | Job console starting...
2025-12-09 00:31:00.620492 | Updating repositories
2025-12-09 00:31:00.754398 | Preparing job workspace
2025-12-09 00:31:04.271078 | Running Ansible setup...
2025-12-09 00:31:08.883186 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-09 00:31:09.473868 | 
2025-12-09 00:31:09.473984 | PLAY [localhost]
2025-12-09 00:31:09.482211 | 
2025-12-09 00:31:09.482281 | TASK [Gathering Facts]
2025-12-09 00:31:10.495003 | localhost | ok
2025-12-09 00:31:10.509893 | 
2025-12-09 00:31:10.510010 | TASK [Setup log path fact]
2025-12-09 00:31:10.531350 | localhost | ok
2025-12-09 00:31:10.548148 | 
2025-12-09 00:31:10.548291 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-09 00:31:10.584657 | localhost | ok
2025-12-09 00:31:10.604905 | 
2025-12-09 00:31:10.605092 | TASK [emit-job-header : Print job information]
2025-12-09 00:31:10.661852 | # Job Information
2025-12-09 00:31:10.662126 | Ansible Version: 2.15.12
2025-12-09 00:31:10.662195 | Job: ansible-test-sanity-docker-devel
2025-12-09 00:31:10.662241 | Pipeline: periodic
2025-12-09 00:31:10.662281 | Executor: ze03.softwarefactory-project.io
2025-12-09 00:31:10.662321 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-12-09 00:31:10.662366 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/1b3/ansible/1b3f5424d4314b30867cd16ef826f4ec/
2025-12-09 00:31:10.662542 | Event ID: af90092fb8e9455a9ddccb9605b9ecd4
2025-12-09 00:31:10.670853 | 
2025-12-09 00:31:10.670987 | LOOP [emit-job-header : Print node information]
2025-12-09 00:31:10.800001 | localhost | ok:
2025-12-09 00:31:10.800277 | localhost | # Node Information
2025-12-09 00:31:10.800339 | localhost | Inventory Hostname: controller
2025-12-09 00:31:10.800382 | localhost | Hostname: np0005551175
2025-12-09 00:31:10.800423 | localhost | Username: zuul
2025-12-09 00:31:10.800470 | localhost | Distro: Fedora 37
2025-12-09 00:31:10.800511 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-12-09 00:31:10.800553 | localhost | Region: ca-ymq-1
2025-12-09 00:31:10.800590 | localhost | Label: ansible-fedora-37-1vcpu
2025-12-09 00:31:10.800627 | localhost | Product Name: OpenStack Nova
2025-12-09 00:31:10.800667 | localhost | Interface IP: 162.253.55.49
2025-12-09 00:31:10.819095 | 
2025-12-09 00:31:10.819233 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-12-09 00:31:11.233303 | localhost -> localhost | changed
2025-12-09 00:31:11.239701 | 
2025-12-09 00:31:11.239843 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-12-09 00:31:12.145112 | localhost -> localhost | changed
2025-12-09 00:31:12.194219 | 
2025-12-09 00:31:12.194334 | PLAY [all:!appliance*]
2025-12-09 00:31:12.219485 | 
2025-12-09 00:31:12.219591 | TASK [include_role : start-zuul-console]
2025-12-09 00:31:12.242838 | controller | ok
2025-12-09 00:31:12.265342 | 
2025-12-09 00:31:12.266025 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-12-09 00:31:12.660643 | controller | ok
2025-12-09 00:31:12.687654 | 
2025-12-09 00:31:12.687837 | TASK [use-our-mirror : Retrieve the IP address]
2025-12-09 00:31:13.717598 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-12-09 00:31:13.727462 | 
2025-12-09 00:31:13.727561 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-12-09 00:31:14.273710 | controller | skipping: Conditional result was False
2025-12-09 00:31:14.288876 | 
2025-12-09 00:31:14.289022 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-12-09 00:31:14.316806 | controller | skipping: Conditional result was False
2025-12-09 00:31:14.334187 | 
2025-12-09 00:31:14.334344 | TASK [use-our-mirror : Create the podman configuration directory]
2025-12-09 00:31:14.362181 | controller | skipping: Conditional result was False
2025-12-09 00:31:14.378007 | 
2025-12-09 00:31:14.378159 | TASK [use-our-mirror : Copy the podman configuration]
2025-12-09 00:31:14.405755 | controller | skipping: Conditional result was False
2025-12-09 00:31:14.423812 | 
2025-12-09 00:31:14.423989 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-12-09 00:31:14.451022 | controller | skipping: Conditional result was False
2025-12-09 00:31:14.468151 | 
2025-12-09 00:31:14.468320 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-12-09 00:31:14.496216 | controller | skipping: Conditional result was False
2025-12-09 00:31:14.525342 | 
2025-12-09 00:31:14.525487 | TASK [Disable Fedora Modular]
2025-12-09 00:31:14.770293 | controller | changed
2025-12-09 00:31:14.784275 | 
2025-12-09 00:31:14.784439 | TASK [Enable EPEL]
2025-12-09 00:31:14.811938 | controller | skipping: Conditional result was False
2025-12-09 00:31:14.831601 | 
2025-12-09 00:31:14.831819 | TASK [Register the RHEL node]
2025-12-09 00:31:15.401657 | 
2025-12-09 00:31:15.401955 | TASK [Show the subscription-manager status]
2025-12-09 00:31:15.993339 | controller | skipping: Conditional result was False
2025-12-09 00:31:16.008359 | 
2025-12-09 00:31:16.008536 | TASK [Enable EPEL on RHEL]
2025-12-09 00:31:16.570264 | controller | skipping: Conditional result was False
2025-12-09 00:31:16.580243 | 
2025-12-09 00:31:16.580358 | TASK [Install git and tox]
2025-12-09 00:32:55.207949 | controller | changed
2025-12-09 00:32:55.216316 | 
2025-12-09 00:32:55.216380 | TASK [include_role : prepare-workspace]
2025-12-09 00:32:55.236340 | controller | ok
2025-12-09 00:32:55.258044 | 
2025-12-09 00:32:55.258160 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-12-09 00:32:55.489369 | controller | ok
2025-12-09 00:32:55.504021 | 
2025-12-09 00:32:55.504242 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-12-09 00:38:42.115024 | controller | Output suppressed because no_log was given
2025-12-09 00:38:42.153032 | 
2025-12-09 00:38:42.153148 | TASK [include_role : prepare-workspace-openshift]
2025-12-09 00:38:42.177699 | controller | skipping: Conditional result was False
2025-12-09 00:38:42.201961 | 
2025-12-09 00:38:42.202034 | PLAY [all:!appliance]
2025-12-09 00:38:42.221148 | 
2025-12-09 00:38:42.221258 | TASK [Run add-build-sshkey role (RSA)]
2025-12-09 00:38:42.252464 | controller | ok
2025-12-09 00:38:42.268132 | 
2025-12-09 00:38:42.268227 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-09 00:38:42.537331 | controller -> localhost | ok
2025-12-09 00:38:42.545010 | 
2025-12-09 00:38:42.545081 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-09 00:38:42.566463 | controller | ok
2025-12-09 00:38:42.580577 | controller | included: /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-09 00:38:42.587026 | 
2025-12-09 00:38:42.587089 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-09 00:38:43.077910 | controller -> localhost | Generating public/private rsa key pair.
2025-12-09 00:38:43.078217 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/work/1b3f5424d4314b30867cd16ef826f4ec_id_rsa.
2025-12-09 00:38:43.078278 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/work/1b3f5424d4314b30867cd16ef826f4ec_id_rsa.pub.
2025-12-09 00:38:43.078325 | controller -> localhost | The key fingerprint is:
2025-12-09 00:38:43.078369 | controller -> localhost | SHA256:fMwodsAlLay0EoheXxxAz8hxdt5BVp19rVytkBXOq4Q zuul-build-sshkey
2025-12-09 00:38:43.078414 | controller -> localhost | The key's randomart image is:
2025-12-09 00:38:43.078456 | controller -> localhost | +---[RSA 2048]----+
2025-12-09 00:38:43.078498 | controller -> localhost | |..  .=+=o..+.++.=|
2025-12-09 00:38:43.078542 | controller -> localhost | |o ..o.X=+ o +o o*|
2025-12-09 00:38:43.078583 | controller -> localhost | |. .o.=++ . . oo+.|
2025-12-09 00:38:43.078624 | controller -> localhost | | .. o. o + .  +. |
2025-12-09 00:38:43.078665 | controller -> localhost | |   .  o S E . .  |
2025-12-09 00:38:43.078721 | controller -> localhost | |     . o . . .   |
2025-12-09 00:38:43.078812 | controller -> localhost | |            .    |
2025-12-09 00:38:43.078880 | controller -> localhost | |                 |
2025-12-09 00:38:43.078928 | controller -> localhost | |                 |
2025-12-09 00:38:43.078974 | controller -> localhost | +----[SHA256]-----+
2025-12-09 00:38:43.079068 | controller -> localhost | ok: Runtime: 0:00:00.065651
2025-12-09 00:38:43.091094 | 
2025-12-09 00:38:43.091195 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-09 00:38:43.128388 | controller | ok
2025-12-09 00:38:43.144265 | controller | included: /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-09 00:38:43.159244 | 
2025-12-09 00:38:43.159357 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-09 00:38:43.185271 | controller | skipping: Conditional result was False
2025-12-09 00:38:43.193073 | 
2025-12-09 00:38:43.193149 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-09 00:38:43.845375 | controller | changed
2025-12-09 00:38:43.862282 | 
2025-12-09 00:38:43.862432 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-09 00:38:44.122637 | controller | ok
2025-12-09 00:38:44.138145 | 
2025-12-09 00:38:44.138287 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-09 00:38:44.783109 | controller | changed
2025-12-09 00:38:44.799429 | 
2025-12-09 00:38:44.799589 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-09 00:38:45.465200 | controller | changed
2025-12-09 00:38:45.479347 | 
2025-12-09 00:38:45.479483 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-09 00:38:45.507458 | controller | skipping: Conditional result was False
2025-12-09 00:38:45.524537 | 
2025-12-09 00:38:45.524678 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-09 00:38:45.973110 | controller -> localhost | changed
2025-12-09 00:38:46.005633 | 
2025-12-09 00:38:46.005843 | TASK [add-build-sshkey : Add back temp key]
2025-12-09 00:38:46.340709 | controller -> localhost | Identity added: /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/work/1b3f5424d4314b30867cd16ef826f4ec_id_rsa (zuul-build-sshkey)
2025-12-09 00:38:46.341197 | controller -> localhost | ok: Runtime: 0:00:00.012745
2025-12-09 00:38:46.357538 | 
2025-12-09 00:38:46.357673 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-09 00:38:46.697209 | controller | ok
2025-12-09 00:38:46.703709 | 
2025-12-09 00:38:46.703795 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-09 00:38:46.738868 | controller | skipping: Conditional result was False
2025-12-09 00:38:46.752203 | 
2025-12-09 00:38:46.752274 | TASK [Run add-build-sshkey role (ECDSA)]
2025-12-09 00:38:46.785359 | controller | ok
2025-12-09 00:38:46.803955 | 
2025-12-09 00:38:46.804039 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-09 00:38:47.083471 | controller -> localhost | ok
2025-12-09 00:38:47.093860 | 
2025-12-09 00:38:47.093959 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-09 00:38:47.134188 | controller | ok
2025-12-09 00:38:47.155600 | controller | included: /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-09 00:38:47.165653 | 
2025-12-09 00:38:47.165800 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-09 00:38:47.497438 | controller -> localhost | Generating public/private ecdsa key pair.
2025-12-09 00:38:47.497808 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/work/1b3f5424d4314b30867cd16ef826f4ec_id_ecdsa.
2025-12-09 00:38:47.497878 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/work/1b3f5424d4314b30867cd16ef826f4ec_id_ecdsa.pub.
2025-12-09 00:38:47.497942 | controller -> localhost | The key fingerprint is:
2025-12-09 00:38:47.497989 | controller -> localhost | SHA256:KIqbBA7s/5FBEe3QxzZA6Cc42+q7VK8xK/23aTXI3MM zuul-build-sshkey
2025-12-09 00:38:47.498033 | controller -> localhost | The key's randomart image is:
2025-12-09 00:38:47.498073 | controller -> localhost | +---[ECDSA 521]---+
2025-12-09 00:38:47.498113 | controller -> localhost | |     o*oo        |
2025-12-09 00:38:47.498152 | controller -> localhost | |     o.o =       |
2025-12-09 00:38:47.498191 | controller -> localhost | |    o.o o .      |
2025-12-09 00:38:47.498229 | controller -> localhost | |.  o.o +         |
2025-12-09 00:38:47.498267 | controller -> localhost | |o.  =o+ S +      |
2025-12-09 00:38:47.498305 | controller -> localhost | |=. o.o+  + E     |
2025-12-09 00:38:47.498343 | controller -> localhost | |.+..o= .  . o    |
2025-12-09 00:38:47.498380 | controller -> localhost | |.ooo .*  o.      |
2025-12-09 00:38:47.498419 | controller -> localhost | |o .==+..oo.      |
2025-12-09 00:38:47.498476 | controller -> localhost | +----[SHA256]-----+
2025-12-09 00:38:47.498588 | controller -> localhost | ok: Runtime: 0:00:00.014210
2025-12-09 00:38:47.517865 | 
2025-12-09 00:38:47.518025 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-09 00:38:47.561528 | controller | ok
2025-12-09 00:38:47.581180 | controller | included: /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-09 00:38:47.596337 | 
2025-12-09 00:38:47.596443 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-09 00:38:47.622661 | controller | skipping: Conditional result was False
2025-12-09 00:38:47.634273 | 
2025-12-09 00:38:47.634369 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-09 00:38:47.913198 | controller | changed
2025-12-09 00:38:47.923662 | 
2025-12-09 00:38:47.923791 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-09 00:38:48.166249 | controller | ok
2025-12-09 00:38:48.180992 | 
2025-12-09 00:38:48.181134 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-09 00:38:48.840054 | controller | changed
2025-12-09 00:38:48.854347 | 
2025-12-09 00:38:48.854481 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-09 00:38:49.507360 | controller | changed
2025-12-09 00:38:49.523765 | 
2025-12-09 00:38:49.523903 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-09 00:38:49.551084 | controller | skipping: Conditional result was False
2025-12-09 00:38:49.607288 | 
2025-12-09 00:38:49.607434 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-09 00:38:49.866310 | controller -> localhost | changed
2025-12-09 00:38:49.879640 | 
2025-12-09 00:38:49.879708 | TASK [add-build-sshkey : Add back temp key]
2025-12-09 00:38:50.214137 | controller -> localhost | Identity added: /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/work/1b3f5424d4314b30867cd16ef826f4ec_id_ecdsa (zuul-build-sshkey)
2025-12-09 00:38:50.214624 | controller -> localhost | ok: Runtime: 0:00:00.012431
2025-12-09 00:38:50.232058 | 
2025-12-09 00:38:50.232200 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-09 00:38:50.462686 | controller | ok
2025-12-09 00:38:50.480141 | 
2025-12-09 00:38:50.480278 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-09 00:38:50.520638 | controller | skipping: Conditional result was False
2025-12-09 00:38:50.551399 | 
2025-12-09 00:38:50.551538 | TASK [include_role : remove-zuul-sshkey]
2025-12-09 00:38:50.579587 | controller | skipping: Conditional result was False
2025-12-09 00:38:50.590799 | 
2025-12-09 00:38:50.590891 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-12-09 00:38:50.831582 | controller | ok: "logs"
2025-12-09 00:38:50.832245 | controller | ok: All items complete
2025-12-09 00:38:50.832535 | 
2025-12-09 00:38:51.017711 | controller | ok: "artifacts"
2025-12-09 00:38:51.214795 | controller | ok: "docs"
2025-12-09 00:38:51.243702 | 
2025-12-09 00:38:51.243884 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-12-09 00:38:51.486314 | controller | changed: "logs"
2025-12-09 00:38:51.689590 | controller | changed: "artifacts"
2025-12-09 00:38:51.893401 | controller | changed: "docs"
2025-12-09 00:38:51.964006 | 
2025-12-09 00:38:51.964113 | PLAY RECAP
2025-12-09 00:38:51.964175 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-12-09 00:38:51.964217 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-09 00:38:51.964243 | 
2025-12-09 00:38:52.077253 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-09 00:38:52.078229 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-09 00:38:52.663354 | 
2025-12-09 00:38:52.663468 | PLAY [all]
2025-12-09 00:38:52.687256 | 
2025-12-09 00:38:52.687370 | TASK [Install binary dependencies]
2025-12-09 00:38:52.760930 | controller | ok
2025-12-09 00:38:52.789111 | 
2025-12-09 00:38:52.789250 | TASK [bindep : Include find tasks]
2025-12-09 00:38:52.833159 | controller | ok
2025-12-09 00:38:52.845051 | controller | included: /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-12-09 00:38:52.854821 | 
2025-12-09 00:38:52.854934 | TASK [bindep : Look for bindep.txt]
2025-12-09 00:38:53.416994 | controller | ok
2025-12-09 00:38:53.433061 | 
2025-12-09 00:38:53.433298 | TASK [bindep : Define bindep_file fact]
2025-12-09 00:38:53.462295 | controller | skipping: Conditional result was False
2025-12-09 00:38:53.471460 | 
2025-12-09 00:38:53.471591 | TASK [bindep : Look for other-requirements.txt]
2025-12-09 00:38:53.689598 | controller | ok
2025-12-09 00:38:53.697662 | 
2025-12-09 00:38:53.697768 | TASK [bindep : Define bindep_file fact]
2025-12-09 00:38:53.732518 | controller | skipping: Conditional result was False
2025-12-09 00:38:53.740087 | 
2025-12-09 00:38:53.740162 | TASK [bindep : Look for bindep fallback file]
2025-12-09 00:38:53.774697 | controller | skipping: Conditional result was False
2025-12-09 00:38:53.791271 | 
2025-12-09 00:38:53.791421 | TASK [bindep : Define bindep_file fact]
2025-12-09 00:38:53.829342 | controller | skipping: Conditional result was False
2025-12-09 00:38:53.844049 | 
2025-12-09 00:38:53.844204 | TASK [bindep : Include bindep tasks]
2025-12-09 00:38:53.881619 | controller | skipping: Conditional result was False
2025-12-09 00:38:53.896502 | 
2025-12-09 00:38:53.896677 | TASK [bindep : Include install tasks]
2025-12-09 00:38:53.933930 | controller | skipping: Conditional result was False
2025-12-09 00:38:53.948580 | 
2025-12-09 00:38:53.948782 | LOOP [bindep : Include package tasks]
2025-12-09 00:38:54.033083 | 
2025-12-09 00:38:54.033280 | TASK [Run test-setup role]
2025-12-09 00:38:54.058677 | controller | ok
2025-12-09 00:38:54.082621 | 
2025-12-09 00:38:54.082707 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-12-09 00:38:54.300183 | controller | ok
2025-12-09 00:38:54.309566 | 
2025-12-09 00:38:54.309651 | TASK [test-setup : Run tools/test-setup.sh]
2025-12-09 00:38:54.855343 | controller | skipping: Conditional result was False
2025-12-09 00:38:54.917389 | 
2025-12-09 00:38:54.917522 | PLAY RECAP
2025-12-09 00:38:54.917591 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-09 00:38:54.917624 | 
2025-12-09 00:38:55.077166 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-09 00:38:55.078881 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-09 00:38:55.700405 | 
2025-12-09 00:38:55.700521 | PLAY [controller]
2025-12-09 00:38:55.722365 | 
2025-12-09 00:38:55.722449 | TASK [Create the /root directory]
2025-12-09 00:38:56.313335 | controller | ok
2025-12-09 00:38:56.328494 | 
2025-12-09 00:38:56.328672 | TASK [Install glibc-langpack-en]
2025-12-09 00:39:00.260222 | controller | ok: Nothing to do
2025-12-09 00:39:00.274974 | 
2025-12-09 00:39:00.275113 | TASK [Ensure controller directory exists]
2025-12-09 00:39:00.499715 | controller | changed
2025-12-09 00:39:00.514955 | 
2025-12-09 00:39:00.515089 | TASK [Install container runtime]
2025-12-09 00:39:00.589149 | controller | ok
2025-12-09 00:39:00.650083 | 
2025-12-09 00:39:00.650180 | LOOP [ensure-podman : Find distribution installation]
2025-12-09 00:39:00.672774 | controller | ok: "/var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-12-09 00:39:00.682199 | controller | included: /var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-12-09 00:39:00.689231 | 
2025-12-09 00:39:00.689296 | TASK [ensure-podman : Install podman (RedHat)]
2025-12-09 00:45:09.169183 | controller | ok: Nothing to do
2025-12-09 00:45:09.186583 | 
2025-12-09 00:45:09.186775 | TASK [ensure-podman : Fetch podman version]
2025-12-09 00:45:09.718174 | controller | Client:       Podman Engine
2025-12-09 00:45:09.748729 | controller | Version:      4.6.2
2025-12-09 00:45:09.748767 | controller | API Version:  4.6.2
2025-12-09 00:45:09.748883 | controller | Go Version:   go1.19.12
2025-12-09 00:45:09.748910 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-12-09 00:45:09.748923 | controller | OS/Arch:      linux/amd64
2025-12-09 00:45:10.241131 | controller | ok: Runtime: 0:00:00.212727
2025-12-09 00:45:10.247850 | 
2025-12-09 00:45:10.247922 | TASK [ensure-podman : Print podman version installed]
2025-12-09 00:45:10.278648 | Podman version: Client:       Podman Engine
2025-12-09 00:45:10.278843 | Version:      4.6.2
2025-12-09 00:45:10.278876 | API Version:  4.6.2
2025-12-09 00:45:10.278901 | Go Version:   go1.19.12
2025-12-09 00:45:10.278926 | Built:        Mon Aug 28 19:38:31 2023
2025-12-09 00:45:10.278952 | OS/Arch:      linux/amd64
2025-12-09 00:45:10.285417 | 
2025-12-09 00:45:10.285487 | TASK [ensure-podman : Validate podman engine]
2025-12-09 00:45:10.818977 | controller | skipping: Conditional result was False
2025-12-09 00:45:10.825792 | 
2025-12-09 00:45:10.825860 | TASK [ensure-podman : Set up docker compatability socket]
2025-12-09 00:45:10.840144 | controller | skipping: Conditional result was False
2025-12-09 00:45:10.852890 | 
2025-12-09 00:45:10.852958 | TASK [Ensure python3.8 is present]
2025-12-09 00:45:10.866870 | controller | skipping: Conditional result was False
2025-12-09 00:45:10.873628 | 
2025-12-09 00:45:10.873717 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-12-09 00:45:10.893013 | controller | ok
2025-12-09 00:45:10.913892 | 
2025-12-09 00:45:10.913977 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-12-09 00:45:12.253936 | controller | ok: Nothing to do
2025-12-09 00:45:12.268311 | 
2025-12-09 00:45:12.268451 | TASK [our-ensure-python : Also install python3-devel]
2025-12-09 00:45:20.730456 | controller | changed
2025-12-09 00:45:20.756323 | 
2025-12-09 00:45:20.756517 | TASK [Run ensure-virtualenv role]
2025-12-09 00:45:20.780146 | controller | ok
2025-12-09 00:45:20.814402 | 
2025-12-09 00:45:20.814542 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-12-09 00:45:21.060765 | controller | /usr/bin/virtualenv
2025-12-09 00:45:21.351572 | controller | ok: Runtime: 0:00:00.004858
2025-12-09 00:45:21.358797 | 
2025-12-09 00:45:21.358877 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-12-09 00:45:21.396782 | controller | skipping: Conditional result was False
2025-12-09 00:45:21.397030 | controller | ok: All items complete
2025-12-09 00:45:21.397058 | 
2025-12-09 00:45:21.416905 | 
2025-12-09 00:45:21.417016 | TASK [Find the full path of the Python interpreter]
2025-12-09 00:45:21.642372 | controller | /usr/bin/python3
2025-12-09 00:45:21.956671 | controller | ok
2025-12-09 00:45:21.971691 | 
2025-12-09 00:45:21.971878 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-12-09 00:45:22.814136 | controller | created virtual environment CPython3.11.0.final.0-64 in 463ms
2025-12-09 00:45:22.843877 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-12-09 00:45:22.843912 | 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-09 00:45:22.843922 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-12-09 00:45:22.843937 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-12-09 00:45:23.032004 | controller | changed
2025-12-09 00:45:23.046469 | 
2025-12-09 00:45:23.046616 | TASK [Set selinux package]
2025-12-09 00:45:23.092688 | controller | ok
2025-12-09 00:45:23.102541 | 
2025-12-09 00:45:23.102630 | TASK [Set selinux package (Fedora)]
2025-12-09 00:45:23.156466 | controller | ok
2025-12-09 00:45:23.164428 | 
2025-12-09 00:45:23.164516 | TASK [Install selinux into virtualenv]
2025-12-09 00:45:24.421859 | controller | Collecting selinux-please-lie-to-me
2025-12-09 00:45:24.462461 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-12-09 00:45:24.784727 | controller | Collecting setuptools<50.0.0
2025-12-09 00:45:24.790983 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-12-09 00:45:24.834780 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 19.4 MB/s eta 0:00:00
2025-12-09 00:45:24.912788 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-12-09 00:45:24.912998 | controller |   Attempting uninstall: setuptools
2025-12-09 00:45:24.915391 | controller |     Found existing installation: setuptools 62.6.0
2025-12-09 00:45:24.974464 | controller |     Uninstalling setuptools-62.6.0:
2025-12-09 00:45:24.982574 | controller |       Successfully uninstalled setuptools-62.6.0
2025-12-09 00:45:25.347630 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-12-09 00:45:25.466641 | controller |
2025-12-09 00:45:25.545092 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-09 00:45:25.545147 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-09 00:45:25.718203 | controller | ok: Runtime: 0:00:02.150890
2025-12-09 00:45:25.724772 | 
2025-12-09 00:45:25.724843 | TASK [Install pytest-forked into virtualenv]
2025-12-09 00:45:26.296505 | controller | Collecting pytest-forked
2025-12-09 00:45:26.336185 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-12-09 00:45:26.386060 | controller | Collecting py
2025-12-09 00:45:26.389646 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-12-09 00:45:26.408052 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 6.0 MB/s eta 0:00:00
2025-12-09 00:45:26.520612 | controller | Collecting pytest>=3.10
2025-12-09 00:45:26.535029 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2025-12-09 00:45:26.550529 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 29.8 MB/s eta 0:00:00
2025-12-09 00:45:26.589384 | controller | Collecting iniconfig>=1.0.1
2025-12-09 00:45:26.593421 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-12-09 00:45:26.630845 | controller | Collecting packaging>=22
2025-12-09 00:45:26.634148 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-12-09 00:45:26.642072 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.3 MB/s eta 0:00:00
2025-12-09 00:45:26.674739 | controller | Collecting pluggy<2,>=1.5
2025-12-09 00:45:26.679931 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-12-09 00:45:26.724798 | controller | Collecting pygments>=2.7.2
2025-12-09 00:45:26.735198 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-12-09 00:45:26.766238 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 53.3 MB/s eta 0:00:00
2025-12-09 00:45:26.839546 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-12-09 00:45:27.920938 | 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-09 00:45:27.929695 | controller |
2025-12-09 00:45:27.998470 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-09 00:45:27.998512 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-09 00:45:28.260285 | controller | ok: Runtime: 0:00:02.073912
2025-12-09 00:45:28.273934 | 
2025-12-09 00:45:28.274077 | TASK [Update pip]
2025-12-09 00:45:28.795889 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-12-09 00:45:28.925743 | controller | Collecting pip
2025-12-09 00:45:28.962932 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-12-09 00:45:29.010604 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 40.2 MB/s eta 0:00:00
2025-12-09 00:45:29.074703 | controller | Installing collected packages: pip
2025-12-09 00:45:29.074917 | controller |   Attempting uninstall: pip
2025-12-09 00:45:29.077050 | controller |     Found existing installation: pip 22.2.2
2025-12-09 00:45:29.213289 | controller |     Uninstalling pip-22.2.2:
2025-12-09 00:45:29.228378 | controller |       Successfully uninstalled pip-22.2.2
2025-12-09 00:45:30.017850 | controller | Successfully installed pip-25.3
2025-12-09 00:45:30.342570 | controller | ok: Runtime: 0:00:01.584558
2025-12-09 00:45:30.356279 | 
2025-12-09 00:45:30.356416 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-12-09 00:45:30.580081 | controller | changed
2025-12-09 00:45:30.594114 | 
2025-12-09 00:45:30.594261 | TASK [Install ansible into virtualenv]
2025-12-09 00:45:31.103305 | controller | Processing ./src/github.com/ansible/ansible
2025-12-09 00:45:31.106621 | controller |   Installing build dependencies: started
2025-12-09 00:45:32.007830 | controller |   Installing build dependencies: finished with status 'done'
2025-12-09 00:45:32.727173 | controller |   Getting requirements to build wheel: started
2025-12-09 00:45:32.727218 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-12-09 00:45:32.728905 | controller |   Preparing metadata (pyproject.toml): started
2025-12-09 00:45:33.196224 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-12-09 00:45:33.199264 | 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-09 00:45:33.201881 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-12-09 00:45:33.663898 | controller | ERROR
2025-12-09 00:45:33.664261 | controller | {
2025-12-09 00:45:33.664325 | controller |   "delta": "0:00:02.438257",
2025-12-09 00:45:33.664590 | controller |   "end": "2025-12-09 00:45:33.265278",
2025-12-09 00:45:33.664656 | controller |   "msg": "non-zero return code",
2025-12-09 00:45:33.664717 | controller |   "rc": 1,
2025-12-09 00:45:33.664792 | controller |   "start": "2025-12-09 00:45:30.827021"
2025-12-09 00:45:33.664829 | controller | }
failure
2025-12-09 00:45:33.667523 | 
2025-12-09 00:45:33.667636 | PLAY RECAP
2025-12-09 00:45:33.667720 | controller | ok: 18 changed: 9 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-12-09 00:45:33.667820 | 
2025-12-09 00:45:33.814805 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-09 00:45:33.815787 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-09 00:45:34.412204 | 
2025-12-09 00:45:34.412319 | PLAY [all]
2025-12-09 00:45:34.434111 | 
2025-12-09 00:45:34.434193 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-12-09 00:45:34.851166 | controller | changed: non-zero return code
2025-12-09 00:45:34.864388 | 
2025-12-09 00:45:34.864551 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-12-09 00:45:34.892817 | controller | skipping: Conditional result was False
2025-12-09 00:45:34.906459 | 
2025-12-09 00:45:34.906616 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-12-09 00:45:34.949108 | 
2025-12-09 00:45:34.949355 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-12-09 00:45:34.990803 | 
2025-12-09 00:45:34.991039 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-12-09 00:45:35.018270 | controller | skipping: Conditional result was False
2025-12-09 00:45:35.033833 | 
2025-12-09 00:45:35.033976 | LOOP [fetch-subunit-output : Generate subunit file]
2025-12-09 00:45:35.074633 | 
2025-12-09 00:45:35.074937 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-12-09 00:45:35.102429 | controller | skipping: Conditional result was False
2025-12-09 00:45:35.112682 | 
2025-12-09 00:45:35.112919 | TASK [fetch-subunit-output : Remove the temporary file]
2025-12-09 00:45:35.140765 | controller | skipping: Conditional result was False
2025-12-09 00:45:35.154617 | 
2025-12-09 00:45:35.154818 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-12-09 00:45:35.182363 | controller | skipping: Conditional result was False
2025-12-09 00:45:35.240970 | 
2025-12-09 00:45:35.241109 | PLAY RECAP
2025-12-09 00:45:35.241168 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-09 00:45:35.241196 | 
2025-12-09 00:45:35.341634 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-09 00:45:35.343373 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-12-09 00:45:35.919315 | 
2025-12-09 00:45:35.919434 | PLAY [all:!appliance*]
2025-12-09 00:45:35.941778 | 
2025-12-09 00:45:35.941873 | TASK [unregister the node]
2025-12-09 00:45:36.475290 | controller | skipping: Conditional result was False
2025-12-09 00:45:36.490023 | 
2025-12-09 00:45:36.490188 | TASK [include_role : fetch-output]
2025-12-09 00:45:36.539340 | controller | ok
2025-12-09 00:45:36.578018 | 
2025-12-09 00:45:36.578150 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-09 00:45:36.655118 | controller | skipping: Conditional result was False
2025-12-09 00:45:36.664209 | 
2025-12-09 00:45:36.664315 | TASK [fetch-output : Set log path for single node]
2025-12-09 00:45:36.727535 | controller | ok
2025-12-09 00:45:36.735608 | 
2025-12-09 00:45:36.735756 | LOOP [fetch-output : Ensure local output dirs]
2025-12-09 00:45:37.243771 | controller -> localhost | ok: "/var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/work/logs"
2025-12-09 00:45:37.517137 | controller -> localhost | changed: "/var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/work/artifacts"
2025-12-09 00:45:37.787099 | controller -> localhost | changed: "/var/lib/zuul/builds/1b3f5424d4314b30867cd16ef826f4ec/work/docs"
2025-12-09 00:45:37.801204 | 
2025-12-09 00:45:37.801353 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-09 00:45:38.435827 | controller | changed:
2025-12-09 00:45:38.436080 | controller | .d..t...... ./
2025-12-09 00:45:38.436120 | controller | cd+++++++++ controller/
2025-12-09 00:45:38.436165 | controller | changed: All items complete
2025-12-09 00:45:38.436195 | 
2025-12-09 00:45:38.946151 | controller | changed: .d..t...... ./
2025-12-09 00:45:39.523952 | controller | changed: .d..t...... ./
2025-12-09 00:45:39.558465 | 
2025-12-09 00:45:39.558685 | TASK [include_role : fetch-output-openshift]
2025-12-09 00:45:39.587604 | controller | skipping: Conditional result was False
2025-12-09 00:45:39.602476 | 
2025-12-09 00:45:39.602633 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-12-09 00:45:39.649961 | controller | skipping: Conditional result was False
2025-12-09 00:45:39.660671 | controller | skipping: Conditional result was False
2025-12-09 00:45:39.707598 | 
2025-12-09 00:45:39.707787 | PLAY [localhost]
2025-12-09 00:45:39.721720 | 
2025-12-09 00:45:39.721850 | TASK [Run Zuul manifest role]
2025-12-09 00:45:39.741130 | localhost | ok
2025-12-09 00:45:39.754211 | 
2025-12-09 00:45:39.754296 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-12-09 00:45:40.114510 | localhost | changed
2025-12-09 00:45:40.125175 | 
2025-12-09 00:45:40.125309 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-12-09 00:45:40.161706 | localhost | ok
2025-12-09 00:45:40.180477 | 
2025-12-09 00:45:40.180629 | TASK [Set zuul-log-path fact]
2025-12-09 00:45:40.202506 | localhost | ok
2025-12-09 00:45:40.223593 | 
2025-12-09 00:45:40.223715 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-09 00:45:40.254823 | localhost | ok
2025-12-09 00:45:40.267239 | 
2025-12-09 00:45:40.267344 | LOOP [Run upload-logs-swift role]
2025-12-09 00:45:40.304180 | localhost | Output suppressed because no_log was given
2025-12-09 00:45:40.342637 | 
2025-12-09 00:45:40.342817 | TASK [Set zuul-log-path fact]
2025-12-09 00:45:40.368303 | localhost | skipping: Conditional result was False
2025-12-09 00:45:40.375616 | 
2025-12-09 00:45:40.375709 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-12-09 00:45:40.822168 | localhost -> localhost | ok: Runtime: 0:00:00.024551
2025-12-09 00:45:40.832783 | 
2025-12-09 00:45:40.832919 | TASK [upload-logs-swift : Upload logs to swift]