2026-01-27 00:28:11.973176 | Job console starting...
2026-01-27 00:28:11.982572 | Updating repositories
2026-01-27 00:28:12.087241 | Preparing job workspace
2026-01-27 00:28:15.671460 | Running Ansible setup...
2026-01-27 00:28:20.563562 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-27 00:28:21.172163 | 
2026-01-27 00:28:21.172306 | PLAY [localhost]
2026-01-27 00:28:21.182101 | 
2026-01-27 00:28:21.182212 | TASK [Gathering Facts]
2026-01-27 00:28:22.251132 | localhost | ok
2026-01-27 00:28:22.271220 | 
2026-01-27 00:28:22.271387 | TASK [Setup log path fact]
2026-01-27 00:28:22.302609 | localhost | ok
2026-01-27 00:28:22.323246 | 
2026-01-27 00:28:22.323424 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-27 00:28:22.366116 | localhost | ok
2026-01-27 00:28:22.379415 | 
2026-01-27 00:28:22.380319 | TASK [emit-job-header : Print job information]
2026-01-27 00:28:22.422719 | # Job Information
2026-01-27 00:28:22.422893 | Ansible Version: 2.15.12
2026-01-27 00:28:22.422927 | Job: ansible-test-sanity-docker-milestone
2026-01-27 00:28:22.422949 | Pipeline: periodic
2026-01-27 00:28:22.422968 | Executor: ze04.softwarefactory-project.io
2026-01-27 00:28:22.422987 | Triggered by: https://github.com/ansible-collections/ansible.network
2026-01-27 00:28:22.423009 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/152/ansible/15220f6202be45eaab6787a1d2c635b3/
2026-01-27 00:28:22.423029 | Event ID: 09a8597d6a8b4d889213d53e421fb5a7
2026-01-27 00:28:22.427093 | 
2026-01-27 00:28:22.427200 | LOOP [emit-job-header : Print node information]
2026-01-27 00:28:22.547582 | localhost | ok:
2026-01-27 00:28:22.548040 | localhost | # Node Information
2026-01-27 00:28:22.548123 | localhost | Inventory Hostname: controller
2026-01-27 00:28:22.548204 | localhost | Hostname: np0005596707
2026-01-27 00:28:22.548277 | localhost | Username: zuul
2026-01-27 00:28:22.548357 | localhost | Distro: Fedora 37
2026-01-27 00:28:22.548425 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2026-01-27 00:28:22.548486 | localhost | Region: ca-ymq-1
2026-01-27 00:28:22.548542 | localhost | Label: ansible-fedora-37-1vcpu
2026-01-27 00:28:22.548584 | localhost | Product Name: OpenStack Nova
2026-01-27 00:28:22.548625 | localhost | Interface IP: 162.253.55.212
2026-01-27 00:28:22.570222 | 
2026-01-27 00:28:22.570415 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2026-01-27 00:28:23.015884 | localhost -> localhost | changed
2026-01-27 00:28:23.028778 | 
2026-01-27 00:28:23.028929 | TASK [log-inventory : Copy ansible inventory to logs dir]
2026-01-27 00:28:24.017301 | localhost -> localhost | changed
2026-01-27 00:28:24.050660 | 
2026-01-27 00:28:24.050757 | PLAY [all:!appliance*]
2026-01-27 00:28:24.067735 | 
2026-01-27 00:28:24.067863 | TASK [include_role : start-zuul-console]
2026-01-27 00:28:24.087756 | controller | ok
2026-01-27 00:28:24.102202 | 
2026-01-27 00:28:24.102306 | TASK [start-zuul-console : Start zuul_console daemon.]
2026-01-27 00:28:24.484193 | controller | ok
2026-01-27 00:28:24.509331 | 
2026-01-27 00:28:24.509505 | TASK [use-our-mirror : Retrieve the IP address]
2026-01-27 00:28:25.617697 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2026-01-27 00:28:25.627905 | 
2026-01-27 00:28:25.628042 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2026-01-27 00:28:26.184062 | controller | skipping: Conditional result was False
2026-01-27 00:28:26.206984 | 
2026-01-27 00:28:26.207138 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2026-01-27 00:28:26.245113 | controller | skipping: Conditional result was False
2026-01-27 00:28:26.262175 | 
2026-01-27 00:28:26.262302 | TASK [use-our-mirror : Create the podman configuration directory]
2026-01-27 00:28:26.298649 | controller | skipping: Conditional result was False
2026-01-27 00:28:26.315512 | 
2026-01-27 00:28:26.315734 | TASK [use-our-mirror : Copy the podman configuration]
2026-01-27 00:28:26.343471 | controller | skipping: Conditional result was False
2026-01-27 00:28:26.352594 | 
2026-01-27 00:28:26.352737 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2026-01-27 00:28:26.378280 | controller | skipping: Conditional result was False
2026-01-27 00:28:26.384915 | 
2026-01-27 00:28:26.385019 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2026-01-27 00:28:26.399760 | controller | skipping: Conditional result was False
2026-01-27 00:28:26.413196 | 
2026-01-27 00:28:26.413282 | TASK [Disable Fedora Modular]
2026-01-27 00:28:26.656412 | controller | changed
2026-01-27 00:28:26.671409 | 
2026-01-27 00:28:26.671558 | TASK [Enable EPEL]
2026-01-27 00:28:26.700106 | controller | skipping: Conditional result was False
2026-01-27 00:28:26.715041 | 
2026-01-27 00:28:26.715266 | TASK [Register the RHEL node]
2026-01-27 00:28:27.287452 | 
2026-01-27 00:28:27.287825 | TASK [Show the subscription-manager status]
2026-01-27 00:28:27.862408 | controller | skipping: Conditional result was False
2026-01-27 00:28:27.875011 | 
2026-01-27 00:28:27.875289 | TASK [Enable EPEL on RHEL]
2026-01-27 00:28:28.428422 | controller | skipping: Conditional result was False
2026-01-27 00:28:28.442497 | 
2026-01-27 00:28:28.442653 | TASK [Install git and tox]
2026-01-27 00:29:55.280649 | controller | changed
2026-01-27 00:29:55.295592 | 
2026-01-27 00:29:55.295793 | TASK [include_role : prepare-workspace]
2026-01-27 00:29:55.322458 | controller | ok
2026-01-27 00:29:55.346555 | 
2026-01-27 00:29:55.346761 | TASK [prepare-workspace : Start zuul_console daemon.]
2026-01-27 00:29:55.563185 | controller | ok
2026-01-27 00:29:55.570256 | 
2026-01-27 00:29:55.570381 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2026-01-27 00:30:08.060973 | controller | Output suppressed because no_log was given
2026-01-27 00:30:08.107727 | 
2026-01-27 00:30:08.107850 | TASK [include_role : prepare-workspace-openshift]
2026-01-27 00:30:08.123727 | controller | skipping: Conditional result was False
2026-01-27 00:30:08.146223 | 
2026-01-27 00:30:08.146298 | PLAY [all:!appliance]
2026-01-27 00:30:08.162723 | 
2026-01-27 00:30:08.162791 | TASK [Run add-build-sshkey role (RSA)]
2026-01-27 00:30:08.183018 | controller | ok
2026-01-27 00:30:08.204072 | 
2026-01-27 00:30:08.204228 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-27 00:30:08.496845 | controller -> localhost | ok
2026-01-27 00:30:08.513168 | 
2026-01-27 00:30:08.513360 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-27 00:30:08.554312 | controller | ok
2026-01-27 00:30:08.583765 | controller | included: /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-27 00:30:08.592734 | 
2026-01-27 00:30:08.592825 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-27 00:30:09.080255 | controller -> localhost | Generating public/private rsa key pair.
2026-01-27 00:30:09.080501 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/work/15220f6202be45eaab6787a1d2c635b3_id_rsa.
2026-01-27 00:30:09.080539 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/work/15220f6202be45eaab6787a1d2c635b3_id_rsa.pub.
2026-01-27 00:30:09.080562 | controller -> localhost | The key fingerprint is:
2026-01-27 00:30:09.080583 | controller -> localhost | SHA256:OXVcoJoCIA+rvPPL0XzLTcFYIMvwi3V+V2AdGzL6zFU zuul-build-sshkey
2026-01-27 00:30:09.080603 | controller -> localhost | The key's randomart image is:
2026-01-27 00:30:09.080623 | controller -> localhost | +---[RSA 2048]----+
2026-01-27 00:30:09.080643 | controller -> localhost | |o .. . .   =o+oE |
2026-01-27 00:30:09.080664 | controller -> localhost | | = .+ o . oo+o+  |
2026-01-27 00:30:09.080708 | controller -> localhost | |. . .= . oo o+   |
2026-01-27 00:30:09.080731 | controller -> localhost | |o   o.+ +=+.o    |
2026-01-27 00:30:09.080750 | controller -> localhost | |.. . ..oS+ =     |
2026-01-27 00:30:09.080780 | controller -> localhost | |  . o  ...o      |
2026-01-27 00:30:09.080817 | controller -> localhost | | o . o . .       |
2026-01-27 00:30:09.080840 | controller -> localhost | |  + . o +        |
2026-01-27 00:30:09.080860 | controller -> localhost | |   +.  o .       |
2026-01-27 00:30:09.080882 | controller -> localhost | +----[SHA256]-----+
2026-01-27 00:30:09.080928 | controller -> localhost | ok: Runtime: 0:00:00.097946
2026-01-27 00:30:09.087819 | 
2026-01-27 00:30:09.087897 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-27 00:30:09.111302 | controller | ok
2026-01-27 00:30:09.123274 | controller | included: /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-27 00:30:09.132411 | 
2026-01-27 00:30:09.132671 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-27 00:30:09.156660 | controller | skipping: Conditional result was False
2026-01-27 00:30:09.162872 | 
2026-01-27 00:30:09.163245 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-27 00:30:09.621126 | controller | changed
2026-01-27 00:30:09.629178 | 
2026-01-27 00:30:09.629269 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-27 00:30:09.869337 | controller | ok
2026-01-27 00:30:09.884073 | 
2026-01-27 00:30:09.884232 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-27 00:30:10.517459 | controller | changed
2026-01-27 00:30:10.528923 | 
2026-01-27 00:30:10.529055 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-27 00:30:11.169128 | controller | changed
2026-01-27 00:30:11.175888 | 
2026-01-27 00:30:11.176520 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-27 00:30:11.202437 | controller | skipping: Conditional result was False
2026-01-27 00:30:11.211278 | 
2026-01-27 00:30:11.211411 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-27 00:30:11.687286 | controller -> localhost | changed
2026-01-27 00:30:11.706392 | 
2026-01-27 00:30:11.706537 | TASK [add-build-sshkey : Add back temp key]
2026-01-27 00:30:12.063364 | controller -> localhost | Identity added: /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/work/15220f6202be45eaab6787a1d2c635b3_id_rsa (zuul-build-sshkey)
2026-01-27 00:30:12.063726 | controller -> localhost | ok: Runtime: 0:00:00.015868
2026-01-27 00:30:12.072500 | 
2026-01-27 00:30:12.072655 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-27 00:30:12.455343 | controller | ok
2026-01-27 00:30:12.463245 | 
2026-01-27 00:30:12.463338 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-27 00:30:12.500718 | controller | skipping: Conditional result was False
2026-01-27 00:30:12.528544 | 
2026-01-27 00:30:12.528743 | TASK [Run add-build-sshkey role (ECDSA)]
2026-01-27 00:30:12.566394 | controller | ok
2026-01-27 00:30:12.592068 | 
2026-01-27 00:30:12.592225 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2026-01-27 00:30:12.852670 | controller -> localhost | ok
2026-01-27 00:30:12.859525 | 
2026-01-27 00:30:12.859604 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2026-01-27 00:30:12.889055 | controller | ok
2026-01-27 00:30:12.900354 | controller | included: /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2026-01-27 00:30:12.906343 | 
2026-01-27 00:30:12.906403 | TASK [add-build-sshkey : Create Temp SSH key]
2026-01-27 00:30:13.164313 | controller -> localhost | Generating public/private ecdsa key pair.
2026-01-27 00:30:13.164489 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/work/15220f6202be45eaab6787a1d2c635b3_id_ecdsa.
2026-01-27 00:30:13.164516 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/work/15220f6202be45eaab6787a1d2c635b3_id_ecdsa.pub.
2026-01-27 00:30:13.164546 | controller -> localhost | The key fingerprint is:
2026-01-27 00:30:13.164566 | controller -> localhost | SHA256:jSvHC20mscgy8UMEAefZpiZVgasfzFsX8/CyHAsSbEY zuul-build-sshkey
2026-01-27 00:30:13.164585 | controller -> localhost | The key's randomart image is:
2026-01-27 00:30:13.164604 | controller -> localhost | +---[ECDSA 521]---+
2026-01-27 00:30:13.164621 | controller -> localhost | |..+oo.           |
2026-01-27 00:30:13.164639 | controller -> localhost | | oE=             |
2026-01-27 00:30:13.164657 | controller -> localhost | | o+.+            |
2026-01-27 00:30:13.164674 | controller -> localhost | | .*+  +  o       |
2026-01-27 00:30:13.164712 | controller -> localhost | |.*+.. .*S .      |
2026-01-27 00:30:13.164730 | controller -> localhost | |.o==o.+=o.       |
2026-01-27 00:30:13.164759 | controller -> localhost | | .o==+==B        |
2026-01-27 00:30:13.164778 | controller -> localhost | |  oo .+B .       |
2026-01-27 00:30:13.164796 | controller -> localhost | |        .        |
2026-01-27 00:30:13.164813 | controller -> localhost | +----[SHA256]-----+
2026-01-27 00:30:13.164855 | controller -> localhost | ok: Runtime: 0:00:00.009978
2026-01-27 00:30:13.171274 | 
2026-01-27 00:30:13.171349 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2026-01-27 00:30:13.191391 | controller | ok
2026-01-27 00:30:13.200014 | controller | included: /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2026-01-27 00:30:13.210104 | 
2026-01-27 00:30:13.210240 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2026-01-27 00:30:13.224471 | controller | skipping: Conditional result was False
2026-01-27 00:30:13.233152 | 
2026-01-27 00:30:13.233284 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2026-01-27 00:35:24.224475 | controller | changed
2026-01-27 00:35:24.235077 | 
2026-01-27 00:35:24.235240 | TASK [add-build-sshkey : Make sure user has a .ssh]
2026-01-27 00:35:24.476906 | controller | ok
2026-01-27 00:35:24.490558 | 
2026-01-27 00:35:24.490738 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2026-01-27 00:35:25.141401 | controller | changed
2026-01-27 00:35:25.155099 | 
2026-01-27 00:35:25.155260 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2026-01-27 00:35:25.790232 | controller | changed
2026-01-27 00:35:25.803379 | 
2026-01-27 00:35:25.803557 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2026-01-27 00:35:25.841023 | controller | skipping: Conditional result was False
2026-01-27 00:35:25.854645 | 
2026-01-27 00:35:25.854833 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2026-01-27 00:35:26.135587 | controller -> localhost | changed
2026-01-27 00:35:26.147610 | 
2026-01-27 00:35:26.147718 | TASK [add-build-sshkey : Add back temp key]
2026-01-27 00:35:26.426171 | controller -> localhost | Identity added: /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/work/15220f6202be45eaab6787a1d2c635b3_id_ecdsa (zuul-build-sshkey)
2026-01-27 00:35:26.426429 | controller -> localhost | ok: Runtime: 0:00:00.011738
2026-01-27 00:35:26.433013 | 
2026-01-27 00:35:26.433091 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2026-01-27 00:35:26.666007 | controller | ok
2026-01-27 00:35:26.672615 | 
2026-01-27 00:35:26.672709 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2026-01-27 00:35:26.707651 | controller | skipping: Conditional result was False
2026-01-27 00:35:26.719993 | 
2026-01-27 00:35:26.720065 | TASK [include_role : remove-zuul-sshkey]
2026-01-27 00:35:26.744468 | controller | skipping: Conditional result was False
2026-01-27 00:35:26.752889 | 
2026-01-27 00:35:26.752956 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2026-01-27 00:35:26.991797 | controller | ok: "logs"
2026-01-27 00:35:26.992323 | controller | ok: All items complete
2026-01-27 00:35:26.992408 | 
2026-01-27 00:35:27.191066 | controller | ok: "artifacts"
2026-01-27 00:35:27.399866 | controller | ok: "docs"
2026-01-27 00:35:27.418209 | 
2026-01-27 00:35:27.418295 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2026-01-27 00:35:27.722103 | controller | changed: "logs"
2026-01-27 00:35:27.974965 | controller | changed: "artifacts"
2026-01-27 00:35:28.176741 | controller | changed: "docs"
2026-01-27 00:35:28.206216 | 
2026-01-27 00:35:28.206326 | PLAY RECAP
2026-01-27 00:35:28.206373 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2026-01-27 00:35:28.206400 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2026-01-27 00:35:28.206418 | 
2026-01-27 00:35:28.323730 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2026-01-27 00:35:28.324838 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-27 00:35:28.898217 | 
2026-01-27 00:35:28.898379 | PLAY [all]
2026-01-27 00:35:28.922299 | 
2026-01-27 00:35:28.922406 | TASK [Install binary dependencies]
2026-01-27 00:35:29.002936 | controller | ok
2026-01-27 00:35:29.023697 | 
2026-01-27 00:35:29.023821 | TASK [bindep : Include find tasks]
2026-01-27 00:35:29.064279 | controller | ok
2026-01-27 00:35:29.073908 | controller | included: /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2026-01-27 00:35:29.081415 | 
2026-01-27 00:35:29.081508 | TASK [bindep : Look for bindep.txt]
2026-01-27 00:35:29.671305 | controller | ok
2026-01-27 00:35:29.684568 | 
2026-01-27 00:35:29.684747 | TASK [bindep : Define bindep_file fact]
2026-01-27 00:35:29.702079 | controller | skipping: Conditional result was False
2026-01-27 00:35:29.717097 | 
2026-01-27 00:35:29.717251 | TASK [bindep : Look for other-requirements.txt]
2026-01-27 00:35:29.949725 | controller | ok
2026-01-27 00:35:29.962221 | 
2026-01-27 00:35:29.962375 | TASK [bindep : Define bindep_file fact]
2026-01-27 00:35:29.989578 | controller | skipping: Conditional result was False
2026-01-27 00:35:30.003882 | 
2026-01-27 00:35:30.004071 | TASK [bindep : Look for bindep fallback file]
2026-01-27 00:35:30.031833 | controller | skipping: Conditional result was False
2026-01-27 00:35:30.047608 | 
2026-01-27 00:35:30.047836 | TASK [bindep : Define bindep_file fact]
2026-01-27 00:35:30.082143 | controller | skipping: Conditional result was False
2026-01-27 00:35:30.109086 | 
2026-01-27 00:35:30.109268 | TASK [bindep : Include bindep tasks]
2026-01-27 00:35:30.135857 | controller | skipping: Conditional result was False
2026-01-27 00:35:30.145955 | 
2026-01-27 00:35:30.146084 | TASK [bindep : Include install tasks]
2026-01-27 00:35:30.171391 | controller | skipping: Conditional result was False
2026-01-27 00:35:30.180270 | 
2026-01-27 00:35:30.180365 | LOOP [bindep : Include package tasks]
2026-01-27 00:35:30.251476 | 
2026-01-27 00:35:30.251714 | TASK [Run test-setup role]
2026-01-27 00:35:30.276075 | controller | ok
2026-01-27 00:35:30.301344 | 
2026-01-27 00:35:30.301451 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2026-01-27 00:35:30.514497 | controller | ok
2026-01-27 00:35:30.520426 | 
2026-01-27 00:35:30.520493 | TASK [test-setup : Run tools/test-setup.sh]
2026-01-27 00:35:31.058886 | controller | skipping: Conditional result was False
2026-01-27 00:35:31.109894 | 
2026-01-27 00:35:31.110055 | PLAY RECAP
2026-01-27 00:35:31.110116 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-27 00:35:31.110146 | 
2026-01-27 00:35:31.221215 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2026-01-27 00:35:31.222844 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-27 00:35:31.841407 | 
2026-01-27 00:35:31.841539 | PLAY [controller]
2026-01-27 00:35:31.864225 | 
2026-01-27 00:35:31.864358 | TASK [Create the /root directory]
2026-01-27 00:35:32.429825 | controller | ok
2026-01-27 00:35:32.444219 | 
2026-01-27 00:35:32.444392 | TASK [Install glibc-langpack-en]
2026-01-27 00:35:36.409518 | controller | ok: Nothing to do
2026-01-27 00:35:36.423048 | 
2026-01-27 00:35:36.424060 | TASK [Ensure controller directory exists]
2026-01-27 00:35:36.643884 | controller | changed
2026-01-27 00:35:36.649925 | 
2026-01-27 00:35:36.649995 | TASK [Install container runtime]
2026-01-27 00:35:36.693015 | controller | ok
2026-01-27 00:35:36.736356 | 
2026-01-27 00:35:36.736495 | LOOP [ensure-podman : Find distribution installation]
2026-01-27 00:35:36.768432 | controller | ok: "/var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2026-01-27 00:35:36.782590 | controller | included: /var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2026-01-27 00:35:36.789391 | 
2026-01-27 00:35:36.789469 | TASK [ensure-podman : Install podman (RedHat)]
2026-01-27 00:36:40.992188 | controller | changed
2026-01-27 00:36:41.005544 | 
2026-01-27 00:36:41.005748 | TASK [ensure-podman : Fetch podman version]
2026-01-27 00:36:41.539366 | controller | Client:       Podman Engine
2026-01-27 00:36:41.539462 | controller | Version:      4.6.2
2026-01-27 00:36:41.539510 | controller | API Version:  4.6.2
2026-01-27 00:36:41.539555 | controller | Go Version:   go1.19.12
2026-01-27 00:36:41.539610 | controller | Built:        Mon Aug 28 19:38:31 2023
2026-01-27 00:36:41.539656 | controller | OS/Arch:      linux/amd64
2026-01-27 00:36:42.058620 | controller | ok: Runtime: 0:00:00.186407
2026-01-27 00:36:42.074591 | 
2026-01-27 00:36:42.074798 | TASK [ensure-podman : Print podman version installed]
2026-01-27 00:36:42.127909 | Podman version: Client:       Podman Engine
2026-01-27 00:36:42.128191 | Version:      4.6.2
2026-01-27 00:36:42.128259 | API Version:  4.6.2
2026-01-27 00:36:42.128307 | Go Version:   go1.19.12
2026-01-27 00:36:42.128354 | Built:        Mon Aug 28 19:38:31 2023
2026-01-27 00:36:42.128401 | OS/Arch:      linux/amd64
2026-01-27 00:36:42.143835 | 
2026-01-27 00:36:42.144031 | TASK [ensure-podman : Validate podman engine]
2026-01-27 00:36:42.691218 | controller | skipping: Conditional result was False
2026-01-27 00:36:42.707555 | 
2026-01-27 00:36:42.707774 | TASK [ensure-podman : Set up docker compatability socket]
2026-01-27 00:36:42.724957 | controller | skipping: Conditional result was False
2026-01-27 00:36:42.741243 | 
2026-01-27 00:36:42.741436 | TASK [Ensure python3.8 is present]
2026-01-27 00:36:42.756135 | controller | skipping: Conditional result was False
2026-01-27 00:36:42.770852 | 
2026-01-27 00:36:42.770960 | TASK [Run our-ensure-python role (Fedora only for now)]
2026-01-27 00:36:42.795027 | controller | ok
2026-01-27 00:36:42.824460 | 
2026-01-27 00:36:42.824596 | TASK [our-ensure-python : Install the right Python version (rpm)]
2026-01-27 00:36:44.208947 | controller | ok: Nothing to do
2026-01-27 00:36:44.222723 | 
2026-01-27 00:36:44.222968 | TASK [our-ensure-python : Also install python3-devel]
2026-01-27 00:36:53.308122 | controller | changed
2026-01-27 00:36:53.324972 | 
2026-01-27 00:36:53.325070 | TASK [Run ensure-virtualenv role]
2026-01-27 00:36:53.345189 | controller | ok
2026-01-27 00:36:53.373383 | 
2026-01-27 00:36:53.373528 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2026-01-27 00:36:53.591794 | controller | /usr/bin/virtualenv
2026-01-27 00:36:53.906077 | controller | ok: Runtime: 0:00:00.005525
2026-01-27 00:36:53.923230 | 
2026-01-27 00:36:53.923411 | LOOP [ensure-virtualenv : Install virtualenv package]
2026-01-27 00:36:53.960251 | controller | skipping: Conditional result was False
2026-01-27 00:36:53.960574 | controller | ok: All items complete
2026-01-27 00:36:53.960615 | 
2026-01-27 00:36:53.977037 | 
2026-01-27 00:36:53.977149 | TASK [Find the full path of the Python interpreter]
2026-01-27 00:36:54.218337 | controller | /usr/bin/python3
2026-01-27 00:36:54.539838 | controller | ok
2026-01-27 00:36:54.553075 | 
2026-01-27 00:36:54.553223 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2026-01-27 00:36:55.320585 | controller | created virtual environment CPython3.11.0.final.0-64 in 426ms
2026-01-27 00:36:55.364474 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2026-01-27 00:36:55.364504 | 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-27 00:36:55.364515 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2026-01-27 00:36:55.364528 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2026-01-27 00:36:55.608843 | controller | changed
2026-01-27 00:36:55.621623 | 
2026-01-27 00:36:55.622036 | TASK [Set selinux package]
2026-01-27 00:36:55.662381 | controller | ok
2026-01-27 00:36:55.680732 | 
2026-01-27 00:36:55.680960 | TASK [Set selinux package (Fedora)]
2026-01-27 00:36:55.737327 | controller | ok
2026-01-27 00:36:55.749059 | 
2026-01-27 00:36:55.749163 | TASK [Install selinux into virtualenv]
2026-01-27 00:37:07.235494 | controller | Collecting selinux-please-lie-to-me
2026-01-27 00:37:19.492181 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2026-01-27 00:37:19.804387 | controller | Collecting setuptools<50.0.0
2026-01-27 00:37:19.808948 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2026-01-27 00:37:19.841731 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 29.6 MB/s eta 0:00:00
2026-01-27 00:37:19.928293 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2026-01-27 00:37:19.928529 | controller |   Attempting uninstall: setuptools
2026-01-27 00:37:19.931089 | controller |     Found existing installation: setuptools 62.6.0
2026-01-27 00:37:19.991727 | controller |     Uninstalling setuptools-62.6.0:
2026-01-27 00:37:19.999805 | controller |       Successfully uninstalled setuptools-62.6.0
2026-01-27 00:37:20.350460 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2026-01-27 00:37:31.864291 | controller |
2026-01-27 00:37:31.951242 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-27 00:37:31.951317 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-27 00:37:32.316285 | controller | ok: Runtime: 0:00:35.962309
2026-01-27 00:37:32.330672 | 
2026-01-27 00:37:32.330896 | TASK [Install pytest-forked into virtualenv]
2026-01-27 00:37:44.111251 | controller | Collecting pytest-forked
2026-01-27 00:37:56.365024 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2026-01-27 00:37:56.566457 | controller | Collecting py
2026-01-27 00:37:56.569954 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2026-01-27 00:37:56.695166 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 737.7 kB/s eta 0:00:00
2026-01-27 00:37:56.836992 | controller | Collecting pytest>=3.10
2026-01-27 00:37:56.841328 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2026-01-27 00:37:56.939716 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 3.9 MB/s eta 0:00:00
2026-01-27 00:37:57.054650 | controller | Collecting iniconfig>=1.0.1
2026-01-27 00:37:57.058231 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2026-01-27 00:37:57.156347 | controller | Collecting packaging>=22
2026-01-27 00:37:57.159848 | controller |   Downloading packaging-26.0-py3-none-any.whl (74 kB)
2026-01-27 00:37:57.261180 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 74.4/74.4 kB 665.2 kB/s eta 0:00:00
2026-01-27 00:37:57.335854 | controller | Collecting pluggy<2,>=1.5
2026-01-27 00:37:57.339550 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2026-01-27 00:37:57.528308 | controller | Collecting pygments>=2.7.2
2026-01-27 00:37:57.531884 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2026-01-27 00:37:57.592309 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 22.0 MB/s eta 0:00:00
2026-01-27 00:37:57.663271 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2026-01-27 00:37:59.299315 | controller | Successfully installed iniconfig-2.3.0 packaging-26.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0
2026-01-27 00:37:59.327967 | controller |
2026-01-27 00:37:59.402813 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2026-01-27 00:37:59.402854 | controller | [notice] To update, run: python -m pip install --upgrade pip
2026-01-27 00:37:59.901816 | controller | ok: Runtime: 0:00:26.842037
2026-01-27 00:37:59.916417 | 
2026-01-27 00:37:59.916573 | TASK [Update pip]
2026-01-27 00:38:00.439750 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2026-01-27 00:38:12.918892 | controller | Collecting pip
2026-01-27 00:38:25.284041 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2026-01-27 00:38:25.360955 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.2 MB/s eta 0:00:00
2026-01-27 00:38:25.424330 | controller | Installing collected packages: pip
2026-01-27 00:38:25.424473 | controller |   Attempting uninstall: pip
2026-01-27 00:38:25.426619 | controller |     Found existing installation: pip 22.2.2
2026-01-27 00:38:25.571950 | controller |     Uninstalling pip-22.2.2:
2026-01-27 00:38:25.587087 | controller |       Successfully uninstalled pip-22.2.2
2026-01-27 00:38:26.373517 | controller | Successfully installed pip-25.3
2026-01-27 00:38:26.480276 | controller | ok: Runtime: 0:00:26.299193
2026-01-27 00:38:26.495873 | 
2026-01-27 00:38:26.496110 | TASK [Ensure pip temp directory exists in /var/tmp]
2026-01-27 00:38:26.720125 | controller | changed
2026-01-27 00:38:26.730550 | 
2026-01-27 00:38:26.730711 | TASK [Install ansible into virtualenv]
2026-01-27 00:38:27.244903 | controller | Processing ./src/github.com/ansible/ansible
2026-01-27 00:38:27.248159 | controller |   Installing build dependencies: started
2026-01-27 00:39:04.450728 | controller |   Installing build dependencies: finished with status 'done'
2026-01-27 00:39:04.452026 | controller |   Getting requirements to build wheel: started
2026-01-27 00:39:05.184935 | controller |   Getting requirements to build wheel: finished with status 'done'
2026-01-27 00:39:05.185867 | controller |   Preparing metadata (pyproject.toml): started
2026-01-27 00:39:05.656475 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2026-01-27 00:39:05.662762 | 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-27 00:39:05.666405 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2026-01-27 00:39:05.801578 | controller | ERROR
2026-01-27 00:39:05.801885 | controller | {
2026-01-27 00:39:05.801951 | controller |   "delta": "0:00:38.770537",
2026-01-27 00:39:05.801994 | controller |   "end": "2026-01-27 00:39:05.735756",
2026-01-27 00:39:05.802031 | controller |   "msg": "non-zero return code",
2026-01-27 00:39:05.802082 | controller |   "rc": 1,
2026-01-27 00:39:05.802119 | controller |   "start": "2026-01-27 00:38:26.965219"
2026-01-27 00:39:05.802154 | controller | }
failure
2026-01-27 00:39:05.804661 | 
2026-01-27 00:39:05.804792 | PLAY RECAP
2026-01-27 00:39:05.804874 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2026-01-27 00:39:05.804918 | 
2026-01-27 00:39:05.932662 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2026-01-27 00:39:05.935528 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-27 00:39:06.533011 | 
2026-01-27 00:39:06.533132 | PLAY [all]
2026-01-27 00:39:06.554461 | 
2026-01-27 00:39:06.554559 | TASK [fetch-subunit-output : Find stestr or testr executable]
2026-01-27 00:39:07.016278 | controller | changed: non-zero return code
2026-01-27 00:39:07.030215 | 
2026-01-27 00:39:07.030464 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2026-01-27 00:39:07.056734 | controller | skipping: Conditional result was False
2026-01-27 00:39:07.066401 | 
2026-01-27 00:39:07.066532 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2026-01-27 00:39:07.091791 | 
2026-01-27 00:39:07.091974 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2026-01-27 00:39:07.116262 | 
2026-01-27 00:39:07.116441 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2026-01-27 00:39:07.132356 | controller | skipping: Conditional result was False
2026-01-27 00:39:07.142747 | 
2026-01-27 00:39:07.142848 | LOOP [fetch-subunit-output : Generate subunit file]
2026-01-27 00:39:07.165914 | 
2026-01-27 00:39:07.166069 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2026-01-27 00:39:07.180798 | controller | skipping: Conditional result was False
2026-01-27 00:39:07.189634 | 
2026-01-27 00:39:07.189761 | TASK [fetch-subunit-output : Remove the temporary file]
2026-01-27 00:39:07.205199 | controller | skipping: Conditional result was False
2026-01-27 00:39:07.213873 | 
2026-01-27 00:39:07.213963 | TASK [fetch-subunit-output : Process and fetch subunit results]
2026-01-27 00:39:07.240094 | controller | skipping: Conditional result was False
2026-01-27 00:39:07.277041 | 
2026-01-27 00:39:07.277207 | PLAY RECAP
2026-01-27 00:39:07.277252 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2026-01-27 00:39:07.277273 | 
2026-01-27 00:39:07.372995 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2026-01-27 00:39:07.373874 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2026-01-27 00:39:07.999663 | 
2026-01-27 00:39:07.999788 | PLAY [all:!appliance*]
2026-01-27 00:39:08.032603 | 
2026-01-27 00:39:08.032753 | TASK [unregister the node]
2026-01-27 00:39:08.565398 | controller | skipping: Conditional result was False
2026-01-27 00:39:08.573729 | 
2026-01-27 00:39:08.573843 | TASK [include_role : fetch-output]
2026-01-27 00:39:08.609476 | controller | ok
2026-01-27 00:39:08.635883 | 
2026-01-27 00:39:08.636073 | TASK [fetch-output : Set log path for multiple nodes]
2026-01-27 00:39:08.690599 | controller | skipping: Conditional result was False
2026-01-27 00:39:08.696853 | 
2026-01-27 00:39:08.696925 | TASK [fetch-output : Set log path for single node]
2026-01-27 00:39:08.729108 | controller | ok
2026-01-27 00:39:08.737607 | 
2026-01-27 00:39:08.737730 | LOOP [fetch-output : Ensure local output dirs]
2026-01-27 00:39:09.128415 | controller -> localhost | ok: "/var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/work/logs"
2026-01-27 00:39:09.350751 | controller -> localhost | changed: "/var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/work/artifacts"
2026-01-27 00:39:09.556395 | controller -> localhost | changed: "/var/lib/zuul/builds/15220f6202be45eaab6787a1d2c635b3/work/docs"
2026-01-27 00:39:09.571944 | 
2026-01-27 00:39:09.572124 | LOOP [fetch-output : Collect logs, artifacts and docs]
2026-01-27 00:39:10.185475 | controller | changed:
2026-01-27 00:39:10.185648 | controller | .d..t...... ./
2026-01-27 00:39:10.185703 | controller | cd+++++++++ controller/
2026-01-27 00:39:10.185741 | controller | changed: All items complete
2026-01-27 00:39:10.185763 | 
2026-01-27 00:39:10.704438 | controller | changed: .d..t...... ./
2026-01-27 00:39:11.213473 | controller | changed: .d..t...... ./
2026-01-27 00:39:11.235620 | 
2026-01-27 00:39:11.235802 | TASK [include_role : fetch-output-openshift]
2026-01-27 00:39:11.260821 | controller | skipping: Conditional result was False
2026-01-27 00:39:11.269927 | 
2026-01-27 00:39:11.270049 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2026-01-27 00:39:11.295318 | controller | skipping: Conditional result was False
2026-01-27 00:39:11.304180 | controller | skipping: Conditional result was False
2026-01-27 00:39:11.333828 | 
2026-01-27 00:39:11.333958 | PLAY [localhost]
2026-01-27 00:39:11.346188 | 
2026-01-27 00:39:11.346286 | TASK [Run Zuul manifest role]
2026-01-27 00:39:11.363828 | localhost | ok
2026-01-27 00:39:11.380980 | 
2026-01-27 00:39:11.381113 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2026-01-27 00:39:11.748889 | localhost | changed
2026-01-27 00:39:11.757393 | 
2026-01-27 00:39:11.757538 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2026-01-27 00:39:11.797022 | localhost | ok
2026-01-27 00:39:11.804824 | 
2026-01-27 00:39:11.804904 | TASK [Set zuul-log-path fact]
2026-01-27 00:39:11.822428 | localhost | ok
2026-01-27 00:39:11.835728 | 
2026-01-27 00:39:11.835830 | TASK [set-zuul-log-path-fact : Set log path for a build]
2026-01-27 00:39:11.882321 | localhost | ok
2026-01-27 00:39:11.891402 | 
2026-01-27 00:39:11.891485 | LOOP [Run upload-logs-swift role]
2026-01-27 00:39:11.926617 | localhost | Output suppressed because no_log was given
2026-01-27 00:39:11.954770 | 
2026-01-27 00:39:11.954894 | TASK [Set zuul-log-path fact]
2026-01-27 00:39:11.979965 | localhost | skipping: Conditional result was False
2026-01-27 00:39:11.985219 | 
2026-01-27 00:39:11.985296 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2026-01-27 00:39:12.400707 | localhost -> localhost | ok: Runtime: 0:00:00.009090
2026-01-27 00:39:12.409900 | 
2026-01-27 00:39:12.410033 | TASK [upload-logs-swift : Upload logs to swift]