2025-10-06 00:20:16.835236 | Job console starting...
2025-10-06 00:20:16.845886 | Updating repositories
2025-10-06 00:20:16.972562 | Preparing job workspace
2025-10-06 00:20:20.677846 | Running Ansible setup...
2025-10-06 00:20:27.286268 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-06 00:20:27.892962 | 
2025-10-06 00:20:27.893098 | PLAY [localhost]
2025-10-06 00:20:27.902384 | 
2025-10-06 00:20:27.902483 | TASK [Gathering Facts]
2025-10-06 00:20:29.019677 | localhost | ok
2025-10-06 00:20:29.033234 | 
2025-10-06 00:20:29.033373 | TASK [Setup log path fact]
2025-10-06 00:20:29.058491 | localhost | ok
2025-10-06 00:20:29.078977 | 
2025-10-06 00:20:29.079124 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-06 00:20:29.119419 | localhost | ok
2025-10-06 00:20:29.131294 | 
2025-10-06 00:20:29.131409 | TASK [emit-job-header : Print job information]
2025-10-06 00:20:29.184643 | # Job Information
2025-10-06 00:20:29.184906 | Ansible Version: 2.15.12
2025-10-06 00:20:29.184977 | Job: ansible-test-sanity-docker-devel
2025-10-06 00:20:29.185023 | Pipeline: periodic
2025-10-06 00:20:29.185064 | Executor: ze03.softwarefactory-project.io
2025-10-06 00:20:29.185102 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-06 00:20:29.185148 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/9a6/ansible/9a62427101364ac2bab6e90492ca6e56/
2025-10-06 00:20:29.185190 | Event ID: 9d310e2ddb83445ab53d82797698fe1c
2025-10-06 00:20:29.194383 | 
2025-10-06 00:20:29.194559 | LOOP [emit-job-header : Print node information]
2025-10-06 00:20:29.313674 | localhost | ok:
2025-10-06 00:20:29.314135 | localhost | # Node Information
2025-10-06 00:20:29.314211 | localhost | Inventory Hostname: controller
2025-10-06 00:20:29.314265 | localhost | Hostname: ip-172-16-139-131
2025-10-06 00:20:29.314310 | localhost | Username: zuul-worker
2025-10-06 00:20:29.314361 | localhost | Distro: Fedora 37
2025-10-06 00:20:29.314404 | localhost | Provider: ansible-us-east-2
2025-10-06 00:20:29.314447 | localhost | Region: us-east-2
2025-10-06 00:20:29.314487 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-06 00:20:29.314527 | localhost | Product Name: t3.small
2025-10-06 00:20:29.314567 | localhost | Interface IP: 18.116.73.156
2025-10-06 00:20:29.336119 | 
2025-10-06 00:20:29.336347 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-06 00:20:29.764669 | localhost -> localhost | changed
2025-10-06 00:20:29.770354 | 
2025-10-06 00:20:29.770442 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-06 00:20:30.727261 | localhost -> localhost | changed
2025-10-06 00:20:30.757211 | 
2025-10-06 00:20:30.757325 | PLAY [all:!appliance*]
2025-10-06 00:20:30.781013 | 
2025-10-06 00:20:30.781092 | TASK [include_role : start-zuul-console]
2025-10-06 00:20:30.799634 | controller | ok
2025-10-06 00:20:30.813391 | 
2025-10-06 00:20:30.813468 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-06 00:20:31.481754 | controller | ok
2025-10-06 00:20:31.507051 | 
2025-10-06 00:20:31.507233 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-06 00:20:35.105149 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-06 00:20:35.116830 | 
2025-10-06 00:20:35.116974 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-06 00:20:35.267578 | controller | skipping: Conditional result was False
2025-10-06 00:20:35.277029 | 
2025-10-06 00:20:35.277167 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-06 00:20:35.302258 | controller | skipping: Conditional result was False
2025-10-06 00:20:35.312036 | 
2025-10-06 00:20:35.312186 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-06 00:20:35.338218 | controller | skipping: Conditional result was False
2025-10-06 00:20:35.348604 | 
2025-10-06 00:20:35.348779 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-06 00:20:35.383827 | controller | skipping: Conditional result was False
2025-10-06 00:20:35.393115 | 
2025-10-06 00:20:35.393262 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-06 00:20:35.418718 | controller | skipping: Conditional result was False
2025-10-06 00:20:35.428117 | 
2025-10-06 00:20:35.428266 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-06 00:20:35.453551 | controller | skipping: Conditional result was False
2025-10-06 00:20:35.469868 | 
2025-10-06 00:20:35.470026 | TASK [Disable Fedora Modular]
2025-10-06 00:20:36.241163 | controller | changed
2025-10-06 00:20:36.256657 | 
2025-10-06 00:20:36.256862 | TASK [Enable EPEL]
2025-10-06 00:20:36.273676 | controller | skipping: Conditional result was False
2025-10-06 00:20:36.286874 | 
2025-10-06 00:20:36.287116 | TASK [Register the RHEL node]
2025-10-06 00:20:36.434946 | 
2025-10-06 00:20:36.435154 | TASK [Show the subscription-manager status]
2025-10-06 00:20:36.612499 | controller | skipping: Conditional result was False
2025-10-06 00:20:36.618543 | 
2025-10-06 00:20:36.618611 | TASK [Enable EPEL on RHEL]
2025-10-06 00:20:36.761894 | controller | skipping: Conditional result was False
2025-10-06 00:20:36.767888 | 
2025-10-06 00:20:36.767958 | TASK [Install git and tox]
2025-10-06 00:22:02.036222 | controller | changed
2025-10-06 00:22:02.043330 | 
2025-10-06 00:22:02.043474 | TASK [include_role : prepare-workspace]
2025-10-06 00:22:02.074185 | controller | ok
2025-10-06 00:22:02.099073 | 
2025-10-06 00:22:02.099209 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-06 00:22:02.652646 | controller | ok
2025-10-06 00:22:02.660978 | 
2025-10-06 00:22:02.661100 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-06 00:22:15.359909 | controller | Output suppressed because no_log was given
2025-10-06 00:22:15.374568 | 
2025-10-06 00:22:15.374656 | TASK [include_role : prepare-workspace-openshift]
2025-10-06 00:22:15.405147 | controller | skipping: Conditional result was False
2025-10-06 00:22:15.461704 | 
2025-10-06 00:22:15.461824 | PLAY [all:!appliance]
2025-10-06 00:22:15.477023 | 
2025-10-06 00:22:15.477094 | TASK [Run add-build-sshkey role (RSA)]
2025-10-06 00:22:15.508875 | controller | ok
2025-10-06 00:22:15.528475 | 
2025-10-06 00:22:15.528554 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-06 00:22:15.837462 | controller -> localhost | ok
2025-10-06 00:22:15.846119 | 
2025-10-06 00:22:15.846210 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-06 00:22:15.866478 | controller | ok
2025-10-06 00:22:15.880258 | controller | included: /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-06 00:22:15.886807 | 
2025-10-06 00:22:15.886895 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-06 00:22:16.353053 | controller -> localhost | Generating public/private rsa key pair.
2025-10-06 00:22:16.353253 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/work/9a62427101364ac2bab6e90492ca6e56_id_rsa.
2025-10-06 00:22:16.353283 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/work/9a62427101364ac2bab6e90492ca6e56_id_rsa.pub.
2025-10-06 00:22:16.353304 | controller -> localhost | The key fingerprint is:
2025-10-06 00:22:16.353323 | controller -> localhost | SHA256:qHgmhQ/Iio4/0M/JfjrNvJiNoES89UY89gq0U7KPd54 zuul-build-sshkey
2025-10-06 00:22:16.353342 | controller -> localhost | The key's randomart image is:
2025-10-06 00:22:16.353360 | controller -> localhost | +---[RSA 2048]----+
2025-10-06 00:22:16.353377 | controller -> localhost | |                 |
2025-10-06 00:22:16.353396 | controller -> localhost | |                 |
2025-10-06 00:22:16.353413 | controller -> localhost | |                 |
2025-10-06 00:22:16.353430 | controller -> localhost | |o. ..  .         |
2025-10-06 00:22:16.353447 | controller -> localhost | |.=o+.*. S        |
2025-10-06 00:22:16.353473 | controller -> localhost | |= ==O.o          |
2025-10-06 00:22:16.353494 | controller -> localhost | |o++O=B .         |
2025-10-06 00:22:16.353514 | controller -> localhost | |+..=%**..        |
2025-10-06 00:22:16.353532 | controller -> localhost | |oo.+B*=E         |
2025-10-06 00:22:16.353552 | controller -> localhost | +----[SHA256]-----+
2025-10-06 00:22:16.353598 | controller -> localhost | ok: Runtime: 0:00:00.072251
2025-10-06 00:22:16.359656 | 
2025-10-06 00:22:16.359717 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-06 00:22:16.391322 | controller | ok
2025-10-06 00:22:16.406574 | controller | included: /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-06 00:22:16.419404 | 
2025-10-06 00:22:16.419495 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-06 00:22:16.435125 | controller | skipping: Conditional result was False
2025-10-06 00:22:16.445047 | 
2025-10-06 00:22:16.445147 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-06 00:22:17.092811 | controller | changed
2025-10-06 00:22:17.098099 | 
2025-10-06 00:22:17.098162 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-06 00:22:17.430824 | controller | ok
2025-10-06 00:22:17.443914 | 
2025-10-06 00:22:17.444106 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-06 00:22:18.728602 | controller | changed
2025-10-06 00:22:18.741111 | 
2025-10-06 00:22:18.741259 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-06 00:22:20.051882 | controller | changed
2025-10-06 00:22:20.066411 | 
2025-10-06 00:22:20.066571 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-06 00:22:20.096222 | controller | skipping: Conditional result was False
2025-10-06 00:22:20.112834 | 
2025-10-06 00:22:20.112986 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-06 00:22:20.519500 | controller -> localhost | changed
2025-10-06 00:22:20.531215 | 
2025-10-06 00:22:20.531325 | TASK [add-build-sshkey : Add back temp key]
2025-10-06 00:22:20.842541 | controller -> localhost | Identity added: /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/work/9a62427101364ac2bab6e90492ca6e56_id_rsa (zuul-build-sshkey)
2025-10-06 00:22:20.843122 | controller -> localhost | ok: Runtime: 0:00:00.016316
2025-10-06 00:22:20.859231 | 
2025-10-06 00:22:20.859374 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-06 00:22:21.377087 | controller | ok
2025-10-06 00:22:21.387293 | 
2025-10-06 00:22:21.387383 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-06 00:22:21.434043 | controller | skipping: Conditional result was False
2025-10-06 00:22:21.462862 | 
2025-10-06 00:22:21.463062 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-06 00:22:21.500687 | controller | ok
2025-10-06 00:22:21.536199 | 
2025-10-06 00:22:21.536360 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-06 00:22:21.839754 | controller -> localhost | ok
2025-10-06 00:22:21.849224 | 
2025-10-06 00:22:21.849354 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-06 00:22:21.877259 | controller | ok
2025-10-06 00:22:21.891204 | controller | included: /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-06 00:22:21.898465 | 
2025-10-06 00:22:21.898587 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-06 00:22:22.219854 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-06 00:22:22.220237 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/work/9a62427101364ac2bab6e90492ca6e56_id_ecdsa.
2025-10-06 00:22:22.220296 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/work/9a62427101364ac2bab6e90492ca6e56_id_ecdsa.pub.
2025-10-06 00:22:22.220355 | controller -> localhost | The key fingerprint is:
2025-10-06 00:22:22.220399 | controller -> localhost | SHA256:Zc2aTZ/BxKEHCT2RSc33jy97CehaWzrF6lR0xjEAAQo zuul-build-sshkey
2025-10-06 00:22:22.220439 | controller -> localhost | The key's randomart image is:
2025-10-06 00:22:22.220478 | controller -> localhost | +---[ECDSA 521]---+
2025-10-06 00:22:22.220515 | controller -> localhost | |     E   .o**X++ |
2025-10-06 00:22:22.220551 | controller -> localhost | |      . .  o*== +|
2025-10-06 00:22:22.220586 | controller -> localhost | |       .  o =o+=.|
2025-10-06 00:22:22.220622 | controller -> localhost | |         o =.ooo.|
2025-10-06 00:22:22.220657 | controller -> localhost | |        S o +.o..|
2025-10-06 00:22:22.220692 | controller -> localhost | |           ..+. .|
2025-10-06 00:22:22.220812 | controller -> localhost | |          .oo....|
2025-10-06 00:22:22.220873 | controller -> localhost | |          o++ ..o|
2025-10-06 00:22:22.220930 | controller -> localhost | |         .o+. .+ |
2025-10-06 00:22:22.220985 | controller -> localhost | +----[SHA256]-----+
2025-10-06 00:22:22.221104 | controller -> localhost | ok: Runtime: 0:00:00.010016
2025-10-06 00:22:22.238993 | 
2025-10-06 00:22:22.239195 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-06 00:22:22.271820 | controller | ok
2025-10-06 00:22:22.287893 | controller | included: /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-06 00:22:22.304106 | 
2025-10-06 00:22:22.304266 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-06 00:22:22.341397 | controller | skipping: Conditional result was False
2025-10-06 00:22:22.352756 | 
2025-10-06 00:22:22.352922 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-06 00:22:22.825967 | controller | changed
2025-10-06 00:22:22.840102 | 
2025-10-06 00:22:22.840293 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-06 00:22:23.190347 | controller | ok
2025-10-06 00:22:23.197963 | 
2025-10-06 00:22:23.198043 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-06 00:22:24.845328 | controller | changed
2025-10-06 00:22:24.857884 | 
2025-10-06 00:22:24.858069 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-06 00:22:26.172929 | controller | changed
2025-10-06 00:22:26.180881 | 
2025-10-06 00:22:26.180967 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-06 00:22:26.216149 | controller | skipping: Conditional result was False
2025-10-06 00:22:26.225542 | 
2025-10-06 00:22:26.225652 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-06 00:22:26.576857 | controller -> localhost | changed
2025-10-06 00:22:26.588478 | 
2025-10-06 00:22:26.588563 | TASK [add-build-sshkey : Add back temp key]
2025-10-06 00:22:26.928682 | controller -> localhost | Identity added: /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/work/9a62427101364ac2bab6e90492ca6e56_id_ecdsa (zuul-build-sshkey)
2025-10-06 00:22:26.928982 | controller -> localhost | ok: Runtime: 0:00:00.009829
2025-10-06 00:22:26.977467 | 
2025-10-06 00:22:26.977590 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-06 00:22:27.337817 | controller | ok
2025-10-06 00:22:27.346336 | 
2025-10-06 00:22:27.346460 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-06 00:22:27.382608 | controller | skipping: Conditional result was False
2025-10-06 00:22:27.411084 | 
2025-10-06 00:22:27.411241 | TASK [include_role : remove-zuul-sshkey]
2025-10-06 00:22:27.436882 | controller | skipping: Conditional result was False
2025-10-06 00:22:27.443785 | 
2025-10-06 00:22:27.443899 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-06 00:22:27.776233 | controller | ok: "logs"
2025-10-06 00:22:27.776850 | controller | ok: All items complete
2025-10-06 00:22:27.776931 | 
2025-10-06 00:22:28.046503 | controller | ok: "artifacts"
2025-10-06 00:22:28.334257 | controller | ok: "docs"
2025-10-06 00:22:28.348296 | 
2025-10-06 00:22:28.348421 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-06 00:22:28.667361 | controller | changed: "logs"
2025-10-06 00:22:28.947502 | controller | changed: "artifacts"
2025-10-06 00:22:29.237650 | controller | changed: "docs"
2025-10-06 00:22:29.279436 | 
2025-10-06 00:22:29.279544 | PLAY RECAP
2025-10-06 00:22:29.279588 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-06 00:22:29.279616 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-06 00:22:29.279648 | 
2025-10-06 00:22:29.412090 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-06 00:22:29.414060 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-06 00:22:30.034621 | 
2025-10-06 00:22:30.034778 | PLAY [all]
2025-10-06 00:22:30.058256 | 
2025-10-06 00:22:30.058400 | TASK [Install binary dependencies]
2025-10-06 00:22:30.109632 | controller | ok
2025-10-06 00:22:30.129276 | 
2025-10-06 00:22:30.129415 | TASK [bindep : Include find tasks]
2025-10-06 00:22:30.159028 | controller | ok
2025-10-06 00:22:30.166794 | controller | included: /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-06 00:22:30.173390 | 
2025-10-06 00:22:30.173487 | TASK [bindep : Look for bindep.txt]
2025-10-06 00:22:30.694172 | controller | ok
2025-10-06 00:22:30.712120 | 
2025-10-06 00:22:30.712403 | TASK [bindep : Define bindep_file fact]
2025-10-06 00:22:30.741716 | controller | skipping: Conditional result was False
2025-10-06 00:22:30.757169 | 
2025-10-06 00:22:30.757343 | TASK [bindep : Look for other-requirements.txt]
2025-10-06 00:22:31.089485 | controller | ok
2025-10-06 00:22:31.098586 | 
2025-10-06 00:22:31.098721 | TASK [bindep : Define bindep_file fact]
2025-10-06 00:22:31.124703 | controller | skipping: Conditional result was False
2025-10-06 00:22:31.134170 | 
2025-10-06 00:22:31.134358 | TASK [bindep : Look for bindep fallback file]
2025-10-06 00:22:31.170806 | controller | skipping: Conditional result was False
2025-10-06 00:22:31.180576 | 
2025-10-06 00:22:31.180703 | TASK [bindep : Define bindep_file fact]
2025-10-06 00:22:31.206070 | controller | skipping: Conditional result was False
2025-10-06 00:22:31.215167 | 
2025-10-06 00:22:31.215310 | TASK [bindep : Include bindep tasks]
2025-10-06 00:22:31.241802 | controller | skipping: Conditional result was False
2025-10-06 00:22:31.252844 | 
2025-10-06 00:22:31.252998 | TASK [bindep : Include install tasks]
2025-10-06 00:22:31.278628 | controller | skipping: Conditional result was False
2025-10-06 00:22:31.287920 | 
2025-10-06 00:22:31.288064 | LOOP [bindep : Include package tasks]
2025-10-06 00:22:31.350022 | 
2025-10-06 00:22:31.350262 | TASK [Run test-setup role]
2025-10-06 00:22:31.373559 | controller | ok
2025-10-06 00:22:31.391817 | 
2025-10-06 00:22:31.391936 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-06 00:22:31.690663 | controller | ok
2025-10-06 00:22:31.700181 | 
2025-10-06 00:22:31.700304 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-06 00:22:31.854237 | controller | skipping: Conditional result was False
2025-10-06 00:22:31.883892 | 
2025-10-06 00:22:31.884007 | PLAY RECAP
2025-10-06 00:22:31.884050 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-06 00:22:31.884070 | 
2025-10-06 00:22:31.996663 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-06 00:22:31.998397 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-06 00:22:32.602450 | 
2025-10-06 00:22:32.602601 | PLAY [controller]
2025-10-06 00:22:32.631797 | 
2025-10-06 00:22:32.631948 | TASK [Create the /root directory]
2025-10-06 00:22:33.363223 | controller | ok
2025-10-06 00:22:33.376199 | 
2025-10-06 00:22:33.376361 | TASK [Install glibc-langpack-en]
2025-10-06 00:22:41.458251 | controller | ok: Nothing to do
2025-10-06 00:22:41.474005 | 
2025-10-06 00:22:41.474200 | TASK [Ensure controller directory exists]
2025-10-06 00:22:41.976403 | controller | changed
2025-10-06 00:22:41.990063 | 
2025-10-06 00:22:41.990265 | TASK [Install container runtime]
2025-10-06 00:22:42.072477 | controller | ok
2025-10-06 00:22:42.134264 | 
2025-10-06 00:22:42.134417 | LOOP [ensure-podman : Find distribution installation]
2025-10-06 00:22:42.188408 | controller | ok: "/var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-06 00:22:42.203252 | controller | included: /var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-06 00:22:42.211266 | 
2025-10-06 00:22:42.211400 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-06 00:23:55.236061 | controller | changed
2025-10-06 00:23:55.250488 | 
2025-10-06 00:23:55.250639 | TASK [ensure-podman : Fetch podman version]
2025-10-06 00:23:55.988535 | controller | Client:       Podman Engine
2025-10-06 00:23:56.015205 | controller | Version:      4.6.2
2025-10-06 00:23:56.015270 | controller | API Version:  4.6.2
2025-10-06 00:23:56.015278 | controller | Go Version:   go1.19.12
2025-10-06 00:23:56.015450 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-06 00:23:56.015457 | controller | OS/Arch:      linux/amd64
2025-10-06 00:23:56.399939 | controller | ok: Runtime: 0:00:00.212019
2025-10-06 00:23:56.409922 | 
2025-10-06 00:23:56.410043 | TASK [ensure-podman : Print podman version installed]
2025-10-06 00:23:56.434004 | Podman version: Client:       Podman Engine
2025-10-06 00:23:56.434214 | Version:      4.6.2
2025-10-06 00:23:56.434256 | API Version:  4.6.2
2025-10-06 00:23:56.434288 | Go Version:   go1.19.12
2025-10-06 00:23:56.434317 | Built:        Mon Aug 28 19:38:31 2023
2025-10-06 00:23:56.434347 | OS/Arch:      linux/amd64
2025-10-06 00:23:56.442272 | 
2025-10-06 00:23:56.442359 | TASK [ensure-podman : Validate podman engine]
2025-10-06 00:23:56.587163 | controller | skipping: Conditional result was False
2025-10-06 00:23:56.596768 | 
2025-10-06 00:23:56.596881 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-06 00:23:56.622472 | controller | skipping: Conditional result was False
2025-10-06 00:23:56.643137 | 
2025-10-06 00:23:56.643346 | TASK [Ensure python3.8 is present]
2025-10-06 00:23:56.669617 | controller | skipping: Conditional result was False
2025-10-06 00:23:56.678910 | 
2025-10-06 00:23:56.679066 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-06 00:23:56.704300 | controller | ok
2025-10-06 00:23:56.742756 | 
2025-10-06 00:23:56.742992 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-06 00:24:00.803822 | controller | ok: Nothing to do
2025-10-06 00:24:00.809846 | 
2025-10-06 00:24:00.809939 | TASK [our-ensure-python : Also install python3-devel]
2025-10-06 00:24:14.061437 | controller | changed
2025-10-06 00:24:14.073092 | 
2025-10-06 00:24:14.073181 | TASK [Run ensure-virtualenv role]
2025-10-06 00:24:14.092917 | controller | ok
2025-10-06 00:24:14.114067 | 
2025-10-06 00:24:14.114181 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-06 00:24:14.474135 | controller | /usr/bin/virtualenv
2025-10-06 00:24:14.745795 | controller | ok: Runtime: 0:00:00.004340
2025-10-06 00:24:14.751767 | 
2025-10-06 00:24:14.751856 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-06 00:24:14.772609 | controller | skipping: Conditional result was False
2025-10-06 00:24:14.772915 | controller | ok: All items complete
2025-10-06 00:24:14.772948 | 
2025-10-06 00:24:14.801069 | 
2025-10-06 00:24:14.801187 | TASK [Find the full path of the Python interpreter]
2025-10-06 00:24:15.195168 | controller | /usr/bin/python3
2025-10-06 00:24:15.515165 | controller | ok
2025-10-06 00:24:15.521167 | 
2025-10-06 00:24:15.521278 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-06 00:24:16.878585 | controller | created virtual environment CPython3.11.0.final.0-64 in 749ms
2025-10-06 00:24:16.919031 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-06 00:24:16.919133 | 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-worker/.local/share/virtualenv)
2025-10-06 00:24:16.919150 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-06 00:24:16.919173 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-06 00:24:17.166665 | controller | changed
2025-10-06 00:24:17.173413 | 
2025-10-06 00:24:17.173507 | TASK [Set selinux package]
2025-10-06 00:24:17.193316 | controller | ok
2025-10-06 00:24:17.198688 | 
2025-10-06 00:24:17.198807 | TASK [Set selinux package (Fedora)]
2025-10-06 00:24:17.228782 | controller | ok
2025-10-06 00:24:17.234638 | 
2025-10-06 00:24:17.234746 | TASK [Install selinux into virtualenv]
2025-10-06 00:24:19.849229 | controller | Collecting selinux-please-lie-to-me
2025-10-06 00:24:19.935612 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-06 00:24:20.473764 | controller | Collecting setuptools<50.0.0
2025-10-06 00:24:20.486893 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-06 00:24:20.604601 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.3 MB/s eta 0:00:00
2025-10-06 00:24:20.758447 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-06 00:24:20.758864 | controller |   Attempting uninstall: setuptools
2025-10-06 00:24:20.763692 | controller |     Found existing installation: setuptools 62.6.0
2025-10-06 00:24:20.875783 | controller |     Uninstalling setuptools-62.6.0:
2025-10-06 00:24:20.890098 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-06 00:24:21.629268 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-06 00:24:21.853794 | controller |
2025-10-06 00:24:22.047167 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-06 00:24:22.047218 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-06 00:24:22.455279 | controller | ok: Runtime: 0:00:04.343642
2025-10-06 00:24:22.467940 | 
2025-10-06 00:24:22.468088 | TASK [Install pytest-forked into virtualenv]
2025-10-06 00:24:23.687937 | controller | Collecting pytest-forked
2025-10-06 00:24:23.772350 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-06 00:24:23.831735 | controller | Collecting py
2025-10-06 00:24:23.844474 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-06 00:24:23.879231 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00
2025-10-06 00:24:24.051843 | controller | Collecting pytest>=3.10
2025-10-06 00:24:24.063891 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-06 00:24:24.122875 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.5 MB/s eta 0:00:00
2025-10-06 00:24:24.178102 | controller | Collecting iniconfig>=1
2025-10-06 00:24:24.190577 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-06 00:24:24.256041 | controller | Collecting packaging>=20
2025-10-06 00:24:24.267808 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-06 00:24:24.279660 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.1 MB/s eta 0:00:00
2025-10-06 00:24:24.324274 | controller | Collecting pluggy<2,>=1.5
2025-10-06 00:24:24.335489 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-06 00:24:24.413521 | controller | Collecting pygments>=2.7.2
2025-10-06 00:24:24.425168 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-06 00:24:24.542745 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.7 MB/s eta 0:00:00
2025-10-06 00:24:24.673511 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-06 00:24:26.901931 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-06 00:24:26.917542 | controller |
2025-10-06 00:24:27.083555 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-06 00:24:27.083600 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-06 00:24:27.159870 | controller | ok: Runtime: 0:00:04.118198
2025-10-06 00:24:27.168344 | 
2025-10-06 00:24:27.168466 | TASK [Update pip]
2025-10-06 00:24:28.225657 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-06 00:24:28.509799 | controller | Collecting pip
2025-10-06 00:24:28.596602 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-06 00:24:28.742542 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 12.4 MB/s eta 0:00:00
2025-10-06 00:24:28.905420 | controller | Installing collected packages: pip
2025-10-06 00:24:28.905735 | controller |   Attempting uninstall: pip
2025-10-06 00:24:28.913394 | controller |     Found existing installation: pip 22.2.2
2025-10-06 00:24:29.234556 | controller |     Uninstalling pip-22.2.2:
2025-10-06 00:24:29.282753 | controller |       Successfully uninstalled pip-22.2.2
2025-10-06 00:24:31.051703 | controller | Successfully installed pip-25.2
2025-10-06 00:24:31.319177 | controller | ok: Runtime: 0:00:03.613575
2025-10-06 00:24:31.325863 | 
2025-10-06 00:24:31.325967 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-06 00:24:31.842345 | controller | changed
2025-10-06 00:24:31.849526 | 
2025-10-06 00:24:31.849632 | TASK [Install ansible into virtualenv]
2025-10-06 00:24:32.906621 | controller | Processing ./src/github.com/ansible/ansible
2025-10-06 00:24:32.913020 | controller |   Installing build dependencies: started
2025-10-06 00:24:34.712490 | controller |   Installing build dependencies: finished with status 'done'
2025-10-06 00:24:36.233371 | controller |   Getting requirements to build wheel: started
2025-10-06 00:24:36.233439 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-06 00:24:37.151343 | controller |   Preparing metadata (pyproject.toml): started
2025-10-06 00:24:37.151397 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-06 00:24:37.152898 | 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-10-06 00:24:37.157504 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-06 00:24:37.502586 | controller | ERROR
2025-10-06 00:24:37.503031 | controller | {
2025-10-06 00:24:37.503103 | controller |   "delta": "0:00:05.016698",
2025-10-06 00:24:37.503146 | controller |   "end": "2025-10-06 00:24:37.301004",
2025-10-06 00:24:37.503186 | controller |   "msg": "non-zero return code",
2025-10-06 00:24:37.503248 | controller |   "rc": 1,
2025-10-06 00:24:37.503288 | controller |   "start": "2025-10-06 00:24:32.284306"
2025-10-06 00:24:37.503325 | controller | }
failure
2025-10-06 00:24:37.507064 | 
2025-10-06 00:24:37.507393 | PLAY RECAP
2025-10-06 00:24:37.507512 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-06 00:24:37.507825 | 
2025-10-06 00:24:37.750873 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-06 00:24:37.752152 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-06 00:24:38.468617 | 
2025-10-06 00:24:38.468774 | PLAY [all]
2025-10-06 00:24:38.494229 | 
2025-10-06 00:24:38.494369 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-06 00:24:39.307690 | controller | changed: non-zero return code
2025-10-06 00:24:39.320063 | 
2025-10-06 00:24:39.320224 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-06 00:24:39.349433 | controller | skipping: Conditional result was False
2025-10-06 00:24:39.363147 | 
2025-10-06 00:24:39.363324 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-06 00:24:39.405788 | 
2025-10-06 00:24:39.406093 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-06 00:24:39.449424 | 
2025-10-06 00:24:39.449863 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-06 00:24:39.479150 | controller | skipping: Conditional result was False
2025-10-06 00:24:39.494828 | 
2025-10-06 00:24:39.495130 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-06 00:24:39.535487 | 
2025-10-06 00:24:39.535834 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-06 00:24:39.563264 | controller | skipping: Conditional result was False
2025-10-06 00:24:39.573600 | 
2025-10-06 00:24:39.573839 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-06 00:24:39.600307 | controller | skipping: Conditional result was False
2025-10-06 00:24:39.615156 | 
2025-10-06 00:24:39.615373 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-06 00:24:39.642159 | controller | skipping: Conditional result was False
2025-10-06 00:24:39.687208 | 
2025-10-06 00:24:39.687390 | PLAY RECAP
2025-10-06 00:24:39.687451 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-06 00:24:39.687482 | 
2025-10-06 00:24:39.846575 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-06 00:24:39.847541 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-06 00:24:40.434313 | 
2025-10-06 00:24:40.434432 | PLAY [all:!appliance*]
2025-10-06 00:24:40.455997 | 
2025-10-06 00:24:40.456130 | TASK [unregister the node]
2025-10-06 00:24:40.582101 | controller | skipping: Conditional result was False
2025-10-06 00:24:40.596008 | 
2025-10-06 00:24:40.596221 | TASK [include_role : fetch-output]
2025-10-06 00:24:40.633287 | controller | ok
2025-10-06 00:24:40.665008 | 
2025-10-06 00:24:40.665166 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-06 00:24:40.743228 | controller | skipping: Conditional result was False
2025-10-06 00:24:40.760416 | 
2025-10-06 00:24:40.760707 | TASK [fetch-output : Set log path for single node]
2025-10-06 00:24:40.816970 | controller | ok
2025-10-06 00:24:40.822667 | 
2025-10-06 00:24:40.822794 | LOOP [fetch-output : Ensure local output dirs]
2025-10-06 00:24:41.242513 | controller -> localhost | ok: "/var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/work/logs"
2025-10-06 00:24:41.480399 | controller -> localhost | changed: "/var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/work/artifacts"
2025-10-06 00:24:41.737924 | controller -> localhost | changed: "/var/lib/zuul/builds/9a62427101364ac2bab6e90492ca6e56/work/docs"
2025-10-06 00:24:41.764259 | 
2025-10-06 00:24:41.764430 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-06 00:24:43.008666 | controller | changed:
2025-10-06 00:24:43.015199 | controller | .d..t...... ./
2025-10-06 00:24:43.015321 | controller | cd+++++++++ controller/
2025-10-06 00:24:43.015426 | controller | changed: All items complete
2025-10-06 00:24:43.015473 | 
2025-10-06 00:24:44.124349 | controller | changed: .d..t...... ./
2025-10-06 00:24:45.192966 | controller | changed: .d..t...... ./
2025-10-06 00:24:45.221414 | 
2025-10-06 00:24:45.221620 | TASK [include_role : fetch-output-openshift]
2025-10-06 00:24:45.238989 | controller | skipping: Conditional result was False
2025-10-06 00:24:45.248379 | 
2025-10-06 00:24:45.248501 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-06 00:24:45.281126 | controller | skipping: Conditional result was False
2025-10-06 00:24:45.293588 | controller | skipping: Conditional result was False
2025-10-06 00:24:45.343799 | 
2025-10-06 00:24:45.343936 | PLAY [localhost]
2025-10-06 00:24:45.362224 | 
2025-10-06 00:24:45.362388 | TASK [Run Zuul manifest role]
2025-10-06 00:24:45.383520 | localhost | ok
2025-10-06 00:24:45.403968 | 
2025-10-06 00:24:45.404112 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-06 00:24:45.819602 | localhost | changed
2025-10-06 00:24:45.830052 | 
2025-10-06 00:24:45.830333 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-06 00:24:45.888505 | localhost | ok
2025-10-06 00:24:45.908710 | 
2025-10-06 00:24:45.908948 | TASK [Set zuul-log-path fact]
2025-10-06 00:24:45.937721 | localhost | ok
2025-10-06 00:24:45.964318 | 
2025-10-06 00:24:45.964461 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-06 00:24:46.006988 | localhost | ok
2025-10-06 00:24:46.022409 | 
2025-10-06 00:24:46.022549 | LOOP [Run upload-logs-swift role]
2025-10-06 00:24:46.058913 | localhost | Output suppressed because no_log was given
2025-10-06 00:24:46.097765 | 
2025-10-06 00:24:46.097892 | TASK [Set zuul-log-path fact]
2025-10-06 00:24:46.122801 | localhost | skipping: Conditional result was False
2025-10-06 00:24:46.128806 | 
2025-10-06 00:24:46.128895 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-06 00:24:46.572400 | localhost -> localhost | ok: Runtime: 0:00:00.006485
2025-10-06 00:24:46.578181 | 
2025-10-06 00:24:46.578275 | TASK [upload-logs-swift : Upload logs to swift]