2025-11-05 00:11:47.964862 | Job console starting...
2025-11-05 00:11:47.980011 | Updating repositories
2025-11-05 00:11:48.141293 | Preparing job workspace
2025-11-05 00:11:52.164490 | Running Ansible setup...
2025-11-05 00:11:58.330931 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-05 00:11:59.188071 | 
2025-11-05 00:11:59.188320 | PLAY [localhost]
2025-11-05 00:11:59.199277 | 
2025-11-05 00:11:59.199454 | TASK [Gathering Facts]
2025-11-05 00:12:00.347205 | localhost | ok
2025-11-05 00:12:00.361356 | 
2025-11-05 00:12:00.361441 | TASK [Setup log path fact]
2025-11-05 00:12:00.381937 | localhost | ok
2025-11-05 00:12:00.398188 | 
2025-11-05 00:12:00.398297 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-05 00:12:00.427149 | localhost | ok
2025-11-05 00:12:00.436409 | 
2025-11-05 00:12:00.436491 | TASK [emit-job-header : Print job information]
2025-11-05 00:12:00.465662 | # Job Information
2025-11-05 00:12:00.465929 | Ansible Version: 2.15.12
2025-11-05 00:12:00.465963 | Job: ansible-test-sanity-docker-devel
2025-11-05 00:12:00.465985 | Pipeline: periodic
2025-11-05 00:12:00.466004 | Executor: ze04.softwarefactory-project.io
2025-11-05 00:12:00.466023 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-05 00:12:00.466046 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/5d8/ansible/5d8b81ee40424845b4381bc96789b8f3/
2025-11-05 00:12:00.466074 | Event ID: f882144cc95d49c4bd339e6865f42051
2025-11-05 00:12:00.470616 | 
2025-11-05 00:12:00.470974 | LOOP [emit-job-header : Print node information]
2025-11-05 00:12:00.614204 | localhost | ok:
2025-11-05 00:12:00.614743 | localhost | # Node Information
2025-11-05 00:12:00.614994 | localhost | Inventory Hostname: controller
2025-11-05 00:12:00.615022 | localhost | Hostname: ip-172-16-161-150
2025-11-05 00:12:00.615043 | localhost | Username: zuul-worker
2025-11-05 00:12:00.615066 | localhost | Distro: Fedora 37
2025-11-05 00:12:00.615084 | localhost | Provider: ansible-us-east-2
2025-11-05 00:12:00.615102 | localhost | Region: us-east-2
2025-11-05 00:12:00.615120 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-05 00:12:00.615137 | localhost | Product Name: t3.small
2025-11-05 00:12:00.615155 | localhost | Interface IP: 18.221.167.66
2025-11-05 00:12:00.628983 | 
2025-11-05 00:12:00.629314 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-05 00:12:01.116287 | localhost -> localhost | changed
2025-11-05 00:12:01.136106 | 
2025-11-05 00:12:01.136348 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-05 00:12:02.223923 | localhost -> localhost | changed
2025-11-05 00:12:02.285853 | 
2025-11-05 00:12:02.286072 | PLAY [all:!appliance*]
2025-11-05 00:12:02.314082 | 
2025-11-05 00:12:02.314261 | TASK [include_role : start-zuul-console]
2025-11-05 00:12:02.346851 | controller | ok
2025-11-05 00:12:02.364255 | 
2025-11-05 00:12:02.364421 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-05 00:12:03.329197 | controller | ok
2025-11-05 00:12:03.344263 | 
2025-11-05 00:12:03.344422 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-05 00:12:05.568778 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-05 00:12:05.587207 | 
2025-11-05 00:12:05.588632 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-05 00:12:05.786460 | controller | skipping: Conditional result was False
2025-11-05 00:12:05.795353 | 
2025-11-05 00:12:05.795525 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-05 00:12:05.850026 | controller | skipping: Conditional result was False
2025-11-05 00:12:05.859906 | 
2025-11-05 00:12:05.860018 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-05 00:12:05.926646 | controller | skipping: Conditional result was False
2025-11-05 00:12:05.937891 | 
2025-11-05 00:12:05.938070 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-05 00:12:06.006393 | controller | skipping: Conditional result was False
2025-11-05 00:12:06.021525 | 
2025-11-05 00:12:06.022813 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-05 00:12:06.102316 | controller | skipping: Conditional result was False
2025-11-05 00:12:06.115665 | 
2025-11-05 00:12:06.115885 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-05 00:12:06.196274 | controller | skipping: Conditional result was False
2025-11-05 00:12:06.229160 | 
2025-11-05 00:12:06.229378 | TASK [Disable Fedora Modular]
2025-11-05 00:12:06.973485 | controller | changed
2025-11-05 00:12:06.984925 | 
2025-11-05 00:12:06.985036 | TASK [Enable EPEL]
2025-11-05 00:12:07.060930 | controller | skipping: Conditional result was False
2025-11-05 00:12:07.070343 | 
2025-11-05 00:12:07.070468 | TASK [Register the RHEL node]
2025-11-05 00:12:07.263224 | 
2025-11-05 00:12:07.263429 | TASK [Show the subscription-manager status]
2025-11-05 00:12:07.530635 | controller | skipping: Conditional result was False
2025-11-05 00:12:07.538937 | 
2025-11-05 00:12:07.539027 | TASK [Enable EPEL on RHEL]
2025-11-05 00:12:08.145470 | controller | skipping: Conditional result was False
2025-11-05 00:12:08.152834 | 
2025-11-05 00:12:08.152942 | TASK [Install git and tox]
2025-11-05 00:13:38.581429 | controller | changed
2025-11-05 00:13:38.592903 | 
2025-11-05 00:13:38.593009 | TASK [include_role : prepare-workspace]
2025-11-05 00:13:38.627260 | controller | ok
2025-11-05 00:13:38.651363 | 
2025-11-05 00:13:38.651469 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-05 00:13:39.199722 | controller | ok
2025-11-05 00:13:39.215301 | 
2025-11-05 00:13:39.215481 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-05 00:13:55.626845 | controller | Output suppressed because no_log was given
2025-11-05 00:13:55.658752 | 
2025-11-05 00:13:55.658940 | TASK [include_role : prepare-workspace-openshift]
2025-11-05 00:13:55.738482 | controller | skipping: Conditional result was False
2025-11-05 00:13:55.819051 | 
2025-11-05 00:13:55.819179 | PLAY [all:!appliance]
2025-11-05 00:13:55.837498 | 
2025-11-05 00:13:55.837646 | TASK [Run add-build-sshkey role (RSA)]
2025-11-05 00:13:55.871614 | controller | ok
2025-11-05 00:13:55.894102 | 
2025-11-05 00:13:55.894290 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-05 00:13:56.209480 | controller -> localhost | ok
2025-11-05 00:13:56.236069 | 
2025-11-05 00:13:56.236324 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-05 00:13:56.297809 | controller | ok
2025-11-05 00:13:56.337144 | controller | included: /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-05 00:13:56.349738 | 
2025-11-05 00:13:56.349855 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-05 00:13:56.931575 | controller -> localhost | Generating public/private rsa key pair.
2025-11-05 00:13:56.931933 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/work/5d8b81ee40424845b4381bc96789b8f3_id_rsa.
2025-11-05 00:13:56.931997 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/work/5d8b81ee40424845b4381bc96789b8f3_id_rsa.pub.
2025-11-05 00:13:56.932043 | controller -> localhost | The key fingerprint is:
2025-11-05 00:13:56.932087 | controller -> localhost | SHA256:Yso2IZwCaCeLIuvPZIWl01C2AM1fjtjhc4tXVaLmyBc zuul-build-sshkey
2025-11-05 00:13:56.932134 | controller -> localhost | The key's randomart image is:
2025-11-05 00:13:56.932176 | controller -> localhost | +---[RSA 2048]----+
2025-11-05 00:13:56.932216 | controller -> localhost | | .+. o     ...   |
2025-11-05 00:13:56.932258 | controller -> localhost | |.  o+...  ...    |
2025-11-05 00:13:56.932298 | controller -> localhost | |oo o=o=  E.      |
2025-11-05 00:13:56.932338 | controller -> localhost | |+.+o**.o+..      |
2025-11-05 00:13:56.932378 | controller -> localhost | |=.++.o*oSo       |
2025-11-05 00:13:56.932435 | controller -> localhost | |oo oo= +.        |
2025-11-05 00:13:56.932483 | controller -> localhost | |.  o= .          |
2025-11-05 00:13:56.932525 | controller -> localhost | |. +. .           |
2025-11-05 00:13:56.932566 | controller -> localhost | | ..o             |
2025-11-05 00:13:56.932611 | controller -> localhost | +----[SHA256]-----+
2025-11-05 00:13:56.932744 | controller -> localhost | ok: Runtime: 0:00:00.158999
2025-11-05 00:13:56.948845 | 
2025-11-05 00:13:56.949008 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-05 00:13:56.976595 | controller | ok
2025-11-05 00:13:57.000536 | controller | included: /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-05 00:13:57.015755 | 
2025-11-05 00:13:57.015862 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-05 00:13:57.031801 | controller | skipping: Conditional result was False
2025-11-05 00:13:57.041433 | 
2025-11-05 00:13:57.041538 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-05 00:13:57.693492 | controller | changed
2025-11-05 00:13:57.707294 | 
2025-11-05 00:13:57.707426 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-05 00:13:58.066634 | controller | ok
2025-11-05 00:13:58.080147 | 
2025-11-05 00:13:58.080285 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-05 00:13:59.363755 | controller | changed
2025-11-05 00:13:59.377625 | 
2025-11-05 00:13:59.377856 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-05 00:14:00.753658 | controller | changed
2025-11-05 00:14:00.769460 | 
2025-11-05 00:14:00.769751 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-05 00:14:00.798895 | controller | skipping: Conditional result was False
2025-11-05 00:14:00.808665 | 
2025-11-05 00:14:00.808972 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-05 00:14:01.286662 | controller -> localhost | changed
2025-11-05 00:14:01.302503 | 
2025-11-05 00:14:01.302657 | TASK [add-build-sshkey : Add back temp key]
2025-11-05 00:14:01.593703 | controller -> localhost | Identity added: /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/work/5d8b81ee40424845b4381bc96789b8f3_id_rsa (zuul-build-sshkey)
2025-11-05 00:14:01.594011 | controller -> localhost | ok: Runtime: 0:00:00.011134
2025-11-05 00:14:01.600967 | 
2025-11-05 00:14:01.601038 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-05 00:14:02.579249 | controller | ok
2025-11-05 00:14:02.586561 | 
2025-11-05 00:14:02.586729 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-05 00:14:02.623237 | controller | skipping: Conditional result was False
2025-11-05 00:14:02.639457 | 
2025-11-05 00:14:02.639672 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-05 00:14:02.673661 | controller | ok
2025-11-05 00:14:02.697168 | 
2025-11-05 00:14:02.697368 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-05 00:14:02.971137 | controller -> localhost | ok
2025-11-05 00:14:02.985230 | 
2025-11-05 00:14:02.985367 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-05 00:14:03.026085 | controller | ok
2025-11-05 00:14:03.050369 | controller | included: /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-05 00:14:03.059169 | 
2025-11-05 00:14:03.059260 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-05 00:14:03.425632 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-05 00:14:03.425985 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/work/5d8b81ee40424845b4381bc96789b8f3_id_ecdsa.
2025-11-05 00:14:03.426030 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/work/5d8b81ee40424845b4381bc96789b8f3_id_ecdsa.pub.
2025-11-05 00:14:03.426072 | controller -> localhost | The key fingerprint is:
2025-11-05 00:14:03.426099 | controller -> localhost | SHA256:7lzekZZH1mCIP6smXHy3xsDlHOlEWGo7Lflb7/ejbXM zuul-build-sshkey
2025-11-05 00:14:03.426125 | controller -> localhost | The key's randomart image is:
2025-11-05 00:14:03.426183 | controller -> localhost | +---[ECDSA 521]---+
2025-11-05 00:14:03.426212 | controller -> localhost | |             o.  |
2025-11-05 00:14:03.426236 | controller -> localhost | |           ..o.  |
2025-11-05 00:14:03.426262 | controller -> localhost | |          . +.o. |
2025-11-05 00:14:03.426460 | controller -> localhost | |           o ==o |
2025-11-05 00:14:03.426519 | controller -> localhost | |        S. .B*+..|
2025-11-05 00:14:03.426552 | controller -> localhost | |       .  o +@=  |
2025-11-05 00:14:03.426576 | controller -> localhost | |       .....*+o..|
2025-11-05 00:14:03.426599 | controller -> localhost | |       ooo.+ o=*E|
2025-11-05 00:14:03.426623 | controller -> localhost | |        ooo .o+oX|
2025-11-05 00:14:03.426648 | controller -> localhost | +----[SHA256]-----+
2025-11-05 00:14:03.426741 | controller -> localhost | ok: Runtime: 0:00:00.012035
2025-11-05 00:14:03.438009 | 
2025-11-05 00:14:03.438099 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-05 00:14:03.471331 | controller | ok
2025-11-05 00:14:03.481605 | controller | included: /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-05 00:14:03.493320 | 
2025-11-05 00:14:03.493395 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-05 00:14:03.517985 | controller | skipping: Conditional result was False
2025-11-05 00:14:03.525237 | 
2025-11-05 00:14:03.525312 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-05 00:14:03.970820 | controller | changed
2025-11-05 00:14:03.988896 | 
2025-11-05 00:14:03.989157 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-05 00:14:04.333953 | controller | ok
2025-11-05 00:14:04.342922 | 
2025-11-05 00:14:04.343061 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-05 00:14:05.632604 | controller | changed
2025-11-05 00:14:05.648908 | 
2025-11-05 00:14:05.649068 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-05 00:14:06.968855 | controller | changed
2025-11-05 00:14:06.976211 | 
2025-11-05 00:14:06.976340 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-05 00:14:07.012467 | controller | skipping: Conditional result was False
2025-11-05 00:14:07.027853 | 
2025-11-05 00:14:07.028046 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-05 00:14:07.313379 | controller -> localhost | changed
2025-11-05 00:14:07.396562 | 
2025-11-05 00:14:07.396762 | TASK [add-build-sshkey : Add back temp key]
2025-11-05 00:14:07.754555 | controller -> localhost | Identity added: /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/work/5d8b81ee40424845b4381bc96789b8f3_id_ecdsa (zuul-build-sshkey)
2025-11-05 00:14:07.755092 | controller -> localhost | ok: Runtime: 0:00:00.010107
2025-11-05 00:14:07.770472 | 
2025-11-05 00:14:07.770613 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-05 00:14:08.122725 | controller | ok
2025-11-05 00:14:08.137732 | 
2025-11-05 00:14:08.137941 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-05 00:14:08.168159 | controller | skipping: Conditional result was False
2025-11-05 00:14:08.187121 | 
2025-11-05 00:14:08.187278 | TASK [include_role : remove-zuul-sshkey]
2025-11-05 00:14:08.214459 | controller | skipping: Conditional result was False
2025-11-05 00:14:08.227897 | 
2025-11-05 00:14:08.228025 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-05 00:14:08.570076 | controller | ok: "logs"
2025-11-05 00:14:08.570991 | controller | ok: All items complete
2025-11-05 00:14:08.571122 | 
2025-11-05 00:14:08.881375 | controller | ok: "artifacts"
2025-11-05 00:14:09.163247 | controller | ok: "docs"
2025-11-05 00:14:09.181857 | 
2025-11-05 00:14:09.182211 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-05 00:14:09.518275 | controller | changed: "logs"
2025-11-05 00:14:09.809466 | controller | changed: "artifacts"
2025-11-05 00:14:10.150512 | controller | changed: "docs"
2025-11-05 00:14:10.197224 | 
2025-11-05 00:14:10.197373 | PLAY RECAP
2025-11-05 00:14:10.197420 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-05 00:14:10.197446 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-05 00:14:10.197465 | 
2025-11-05 00:14:10.337634 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-05 00:14:10.339412 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-05 00:14:11.031009 | 
2025-11-05 00:14:11.031148 | PLAY [all]
2025-11-05 00:14:11.056098 | 
2025-11-05 00:14:11.056268 | TASK [Install binary dependencies]
2025-11-05 00:14:11.132904 | controller | ok
2025-11-05 00:14:11.160206 | 
2025-11-05 00:14:11.160380 | TASK [bindep : Include find tasks]
2025-11-05 00:14:11.211981 | controller | ok
2025-11-05 00:14:11.246802 | controller | included: /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-05 00:14:11.253001 | 
2025-11-05 00:14:11.253070 | TASK [bindep : Look for bindep.txt]
2025-11-05 00:14:11.815820 | controller | ok
2025-11-05 00:14:11.833246 | 
2025-11-05 00:14:11.833529 | TASK [bindep : Define bindep_file fact]
2025-11-05 00:14:11.863877 | controller | skipping: Conditional result was False
2025-11-05 00:14:11.873220 | 
2025-11-05 00:14:11.873323 | TASK [bindep : Look for other-requirements.txt]
2025-11-05 00:14:12.818219 | controller | ok
2025-11-05 00:14:12.827954 | 
2025-11-05 00:14:12.828191 | TASK [bindep : Define bindep_file fact]
2025-11-05 00:14:12.855079 | controller | skipping: Conditional result was False
2025-11-05 00:14:12.864868 | 
2025-11-05 00:14:12.865075 | TASK [bindep : Look for bindep fallback file]
2025-11-05 00:14:12.904773 | controller | skipping: Conditional result was False
2025-11-05 00:14:12.915997 | 
2025-11-05 00:14:12.916113 | TASK [bindep : Define bindep_file fact]
2025-11-05 00:14:12.943003 | controller | skipping: Conditional result was False
2025-11-05 00:14:12.951825 | 
2025-11-05 00:14:12.951918 | TASK [bindep : Include bindep tasks]
2025-11-05 00:14:12.978985 | controller | skipping: Conditional result was False
2025-11-05 00:14:12.988523 | 
2025-11-05 00:14:12.988655 | TASK [bindep : Include install tasks]
2025-11-05 00:14:13.017162 | controller | skipping: Conditional result was False
2025-11-05 00:14:13.026514 | 
2025-11-05 00:14:13.026640 | LOOP [bindep : Include package tasks]
2025-11-05 00:14:13.089887 | 
2025-11-05 00:14:13.090146 | TASK [Run test-setup role]
2025-11-05 00:14:13.116255 | controller | ok
2025-11-05 00:14:13.144750 | 
2025-11-05 00:14:13.144917 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-05 00:14:13.546562 | controller | ok
2025-11-05 00:14:13.553058 | 
2025-11-05 00:14:13.553129 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-05 00:14:13.689929 | controller | skipping: Conditional result was False
2025-11-05 00:14:13.723546 | 
2025-11-05 00:14:13.723639 | PLAY RECAP
2025-11-05 00:14:13.723741 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-05 00:14:13.723780 | 
2025-11-05 00:14:13.853947 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-05 00:14:13.854875 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-05 00:14:14.645187 | 
2025-11-05 00:14:14.645458 | PLAY [controller]
2025-11-05 00:14:14.678922 | 
2025-11-05 00:14:14.679161 | TASK [Create the /root directory]
2025-11-05 00:14:15.524108 | controller | ok
2025-11-05 00:14:15.531487 | 
2025-11-05 00:14:15.531658 | TASK [Install glibc-langpack-en]
2025-11-05 00:14:23.666508 | controller | ok: Nothing to do
2025-11-05 00:14:23.672617 | 
2025-11-05 00:14:23.672715 | TASK [Ensure controller directory exists]
2025-11-05 00:14:24.073570 | controller | changed
2025-11-05 00:14:24.080217 | 
2025-11-05 00:14:24.080314 | TASK [Install container runtime]
2025-11-05 00:14:24.153862 | controller | ok
2025-11-05 00:14:24.199126 | 
2025-11-05 00:14:24.199286 | LOOP [ensure-podman : Find distribution installation]
2025-11-05 00:14:24.228089 | controller | ok: "/var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-05 00:14:24.251385 | controller | included: /var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-05 00:14:24.258084 | 
2025-11-05 00:14:24.258164 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-05 00:15:42.710827 | controller | changed
2025-11-05 00:15:42.722083 | 
2025-11-05 00:15:42.722181 | TASK [ensure-podman : Fetch podman version]
2025-11-05 00:15:43.466817 | controller | Client:       Podman Engine
2025-11-05 00:15:43.466899 | controller | Version:      4.6.2
2025-11-05 00:15:43.466930 | controller | API Version:  4.6.2
2025-11-05 00:15:43.466957 | controller | Go Version:   go1.19.12
2025-11-05 00:15:43.466993 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-05 00:15:43.467021 | controller | OS/Arch:      linux/amd64
2025-11-05 00:15:43.882228 | controller | ok: Runtime: 0:00:00.216663
2025-11-05 00:15:43.890381 | 
2025-11-05 00:15:43.890497 | TASK [ensure-podman : Print podman version installed]
2025-11-05 00:15:43.932296 | Podman version: Client:       Podman Engine
2025-11-05 00:15:43.932484 | Version:      4.6.2
2025-11-05 00:15:43.932513 | API Version:  4.6.2
2025-11-05 00:15:43.932534 | Go Version:   go1.19.12
2025-11-05 00:15:43.932552 | Built:        Mon Aug 28 19:38:31 2023
2025-11-05 00:15:43.932574 | OS/Arch:      linux/amd64
2025-11-05 00:15:43.938409 | 
2025-11-05 00:15:43.938491 | TASK [ensure-podman : Validate podman engine]
2025-11-05 00:15:44.073283 | controller | skipping: Conditional result was False
2025-11-05 00:15:44.087929 | 
2025-11-05 00:15:44.088170 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-05 00:15:44.116515 | controller | skipping: Conditional result was False
2025-11-05 00:15:44.131733 | 
2025-11-05 00:15:44.131870 | TASK [Ensure python3.8 is present]
2025-11-05 00:15:44.170072 | controller | skipping: Conditional result was False
2025-11-05 00:15:44.180296 | 
2025-11-05 00:15:44.180427 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-05 00:15:44.202868 | controller | ok
2025-11-05 00:15:44.239093 | 
2025-11-05 00:15:44.239240 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-05 00:15:47.947637 | controller | ok: Nothing to do
2025-11-05 00:15:47.955549 | 
2025-11-05 00:15:47.955881 | TASK [our-ensure-python : Also install python3-devel]
2025-11-05 00:16:02.017973 | controller | changed
2025-11-05 00:16:02.029649 | 
2025-11-05 00:16:02.029774 | TASK [Run ensure-virtualenv role]
2025-11-05 00:16:02.050457 | controller | ok
2025-11-05 00:16:02.077338 | 
2025-11-05 00:16:02.077477 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-05 00:16:02.790533 | controller | /usr/bin/virtualenv
2025-11-05 00:16:03.222704 | controller | ok: Runtime: 0:00:00.007495
2025-11-05 00:16:03.234635 | 
2025-11-05 00:16:03.234800 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-05 00:16:03.270249 | controller | skipping: Conditional result was False
2025-11-05 00:16:03.270563 | controller | ok: All items complete
2025-11-05 00:16:03.270592 | 
2025-11-05 00:16:03.293701 | 
2025-11-05 00:16:03.293922 | TASK [Find the full path of the Python interpreter]
2025-11-05 00:16:03.822686 | controller | /usr/bin/python3
2025-11-05 00:16:04.003041 | controller | ok
2025-11-05 00:16:04.015157 | 
2025-11-05 00:16:04.015282 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-05 00:16:05.431644 | controller | created virtual environment CPython3.11.0.final.0-64 in 754ms
2025-11-05 00:16:05.472730 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-05 00:16:05.472787 | 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-11-05 00:16:05.472803 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-05 00:16:05.472826 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-05 00:16:05.669295 | controller | changed
2025-11-05 00:16:05.675730 | 
2025-11-05 00:16:05.675808 | TASK [Set selinux package]
2025-11-05 00:16:05.696333 | controller | ok
2025-11-05 00:16:05.702011 | 
2025-11-05 00:16:05.702079 | TASK [Set selinux package (Fedora)]
2025-11-05 00:16:05.732493 | controller | ok
2025-11-05 00:16:05.737439 | 
2025-11-05 00:16:05.737503 | TASK [Install selinux into virtualenv]
2025-11-05 00:16:08.356660 | controller | Collecting selinux-please-lie-to-me
2025-11-05 00:16:08.448789 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-05 00:16:08.978074 | controller | Collecting setuptools<50.0.0
2025-11-05 00:16:08.993188 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-05 00:16:09.066233 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 11.8 MB/s eta 0:00:00
2025-11-05 00:16:09.220075 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-05 00:16:09.220375 | controller |   Attempting uninstall: setuptools
2025-11-05 00:16:09.225345 | controller |     Found existing installation: setuptools 62.6.0
2025-11-05 00:16:09.336534 | controller |     Uninstalling setuptools-62.6.0:
2025-11-05 00:16:09.351877 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-05 00:16:10.138284 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-05 00:16:10.367894 | controller |
2025-11-05 00:16:10.588728 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-05 00:16:10.588773 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-05 00:16:10.899550 | controller | ok: Runtime: 0:00:04.381887
2025-11-05 00:16:10.915038 | 
2025-11-05 00:16:10.915258 | TASK [Install pytest-forked into virtualenv]
2025-11-05 00:16:12.135471 | controller | Collecting pytest-forked
2025-11-05 00:16:12.228415 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-05 00:16:12.288311 | controller | Collecting py
2025-11-05 00:16:12.302688 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-05 00:16:12.338845 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-11-05 00:16:12.512321 | controller | Collecting pytest>=3.10
2025-11-05 00:16:12.526908 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-11-05 00:16:12.588418 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.2 MB/s eta 0:00:00
2025-11-05 00:16:12.646634 | controller | Collecting iniconfig>=1
2025-11-05 00:16:12.661472 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-05 00:16:12.729494 | controller | Collecting packaging>=20
2025-11-05 00:16:12.744218 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-05 00:16:12.756760 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.6 MB/s eta 0:00:00
2025-11-05 00:16:12.801947 | controller | Collecting pluggy<2,>=1.5
2025-11-05 00:16:12.816251 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-05 00:16:12.890273 | controller | Collecting pygments>=2.7.2
2025-11-05 00:16:12.904071 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-05 00:16:13.036469 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.5 MB/s eta 0:00:00
2025-11-05 00:16:13.169569 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-05 00:16:15.498839 | controller | Successfully installed iniconfig-2.3.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-11-05 00:16:15.515011 | controller |
2025-11-05 00:16:15.703596 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-05 00:16:15.703641 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-05 00:16:16.484319 | controller | ok: Runtime: 0:00:04.292612
2025-11-05 00:16:16.501566 | 
2025-11-05 00:16:16.501844 | TASK [Update pip]
2025-11-05 00:16:17.597165 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-05 00:16:17.860129 | controller | Collecting pip
2025-11-05 00:16:17.961958 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-05 00:16:18.182002 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.3 MB/s eta 0:00:00
2025-11-05 00:16:18.306090 | controller | Installing collected packages: pip
2025-11-05 00:16:18.306515 | controller |   Attempting uninstall: pip
2025-11-05 00:16:18.311035 | controller |     Found existing installation: pip 22.2.2
2025-11-05 00:16:18.568031 | controller |     Uninstalling pip-22.2.2:
2025-11-05 00:16:18.597579 | controller |       Successfully uninstalled pip-22.2.2
2025-11-05 00:16:20.365248 | controller | Successfully installed pip-25.3
2025-11-05 00:16:20.688844 | controller | ok: Runtime: 0:00:03.613871
2025-11-05 00:16:20.694235 | 
2025-11-05 00:16:20.694297 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-05 00:16:21.203579 | controller | changed
2025-11-05 00:16:21.212743 | 
2025-11-05 00:16:21.212925 | TASK [Install ansible into virtualenv]
2025-11-05 00:16:22.263951 | controller | Processing ./src/github.com/ansible/ansible
2025-11-05 00:16:22.270396 | controller |   Installing build dependencies: started
2025-11-05 00:16:24.382210 | controller |   Installing build dependencies: finished with status 'done'
2025-11-05 00:16:25.997752 | controller |   Getting requirements to build wheel: started
2025-11-05 00:16:25.997814 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-05 00:16:26.995755 | controller |   Preparing metadata (pyproject.toml): started
2025-11-05 00:16:26.995809 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-05 00:16:26.999140 | 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-11-05 00:16:27.004069 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-05 00:16:27.361852 | controller | ERROR
2025-11-05 00:16:27.362179 | controller | {
2025-11-05 00:16:27.362248 | controller |   "delta": "0:00:05.454567",
2025-11-05 00:16:27.362290 | controller |   "end": "2025-11-05 00:16:27.148600",
2025-11-05 00:16:27.362328 | controller |   "msg": "non-zero return code",
2025-11-05 00:16:27.362395 | controller |   "rc": 1,
2025-11-05 00:16:27.362452 | controller |   "start": "2025-11-05 00:16:21.694033"
2025-11-05 00:16:27.362500 | controller | }
failure
2025-11-05 00:16:27.365953 | 
2025-11-05 00:16:27.366056 | PLAY RECAP
2025-11-05 00:16:27.366142 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-05 00:16:27.366185 | 
2025-11-05 00:16:27.514773 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-05 00:16:27.516025 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-05 00:16:28.124494 | 
2025-11-05 00:16:28.124627 | PLAY [all]
2025-11-05 00:16:28.148069 | 
2025-11-05 00:16:28.148197 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-05 00:16:28.933297 | controller | changed: non-zero return code
2025-11-05 00:16:28.946943 | 
2025-11-05 00:16:28.947189 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-05 00:16:28.975072 | controller | skipping: Conditional result was False
2025-11-05 00:16:28.987906 | 
2025-11-05 00:16:28.988078 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-05 00:16:29.031211 | 
2025-11-05 00:16:29.031504 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-05 00:16:29.074249 | 
2025-11-05 00:16:29.074565 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-05 00:16:29.102539 | controller | skipping: Conditional result was False
2025-11-05 00:16:29.117589 | 
2025-11-05 00:16:29.117802 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-05 00:16:29.165530 | 
2025-11-05 00:16:29.165911 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-05 00:16:29.194317 | controller | skipping: Conditional result was False
2025-11-05 00:16:29.210991 | 
2025-11-05 00:16:29.211182 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-05 00:16:29.238888 | controller | skipping: Conditional result was False
2025-11-05 00:16:29.252582 | 
2025-11-05 00:16:29.252774 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-05 00:16:29.270165 | controller | skipping: Conditional result was False
2025-11-05 00:16:29.328330 | 
2025-11-05 00:16:29.328554 | PLAY RECAP
2025-11-05 00:16:29.328611 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-05 00:16:29.328640 | 
2025-11-05 00:16:29.450187 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-05 00:16:29.451984 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-05 00:16:30.060536 | 
2025-11-05 00:16:30.060700 | PLAY [all:!appliance*]
2025-11-05 00:16:30.083781 | 
2025-11-05 00:16:30.083905 | TASK [unregister the node]
2025-11-05 00:16:30.219786 | controller | skipping: Conditional result was False
2025-11-05 00:16:30.234471 | 
2025-11-05 00:16:30.234654 | TASK [include_role : fetch-output]
2025-11-05 00:16:30.296773 | controller | ok
2025-11-05 00:16:30.338181 | 
2025-11-05 00:16:30.338305 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-05 00:16:30.415905 | controller | skipping: Conditional result was False
2025-11-05 00:16:30.429849 | 
2025-11-05 00:16:30.430014 | TASK [fetch-output : Set log path for single node]
2025-11-05 00:16:30.490233 | controller | ok
2025-11-05 00:16:30.503029 | 
2025-11-05 00:16:30.503175 | LOOP [fetch-output : Ensure local output dirs]
2025-11-05 00:16:31.051129 | controller -> localhost | ok: "/var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/work/logs"
2025-11-05 00:16:31.294208 | controller -> localhost | changed: "/var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/work/artifacts"
2025-11-05 00:16:31.500848 | controller -> localhost | changed: "/var/lib/zuul/builds/5d8b81ee40424845b4381bc96789b8f3/work/docs"
2025-11-05 00:16:31.512407 | 
2025-11-05 00:16:31.512569 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-05 00:16:32.755616 | controller | changed:
2025-11-05 00:16:32.756151 | controller | .d..t...... ./
2025-11-05 00:16:32.756317 | controller | cd+++++++++ controller/
2025-11-05 00:16:32.756423 | controller | changed: All items complete
2025-11-05 00:16:32.756470 | 
2025-11-05 00:16:34.065839 | controller | changed: .d..t...... ./
2025-11-05 00:16:35.157706 | controller | changed: .d..t...... ./
2025-11-05 00:16:35.184891 | 
2025-11-05 00:16:35.185177 | TASK [include_role : fetch-output-openshift]
2025-11-05 00:16:35.212422 | controller | skipping: Conditional result was False
2025-11-05 00:16:35.221578 | 
2025-11-05 00:16:35.221747 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-05 00:16:35.269634 | controller | skipping: Conditional result was False
2025-11-05 00:16:35.282094 | controller | skipping: Conditional result was False
2025-11-05 00:16:35.326432 | 
2025-11-05 00:16:35.326578 | PLAY [localhost]
2025-11-05 00:16:35.338672 | 
2025-11-05 00:16:35.338816 | TASK [Run Zuul manifest role]
2025-11-05 00:16:35.358585 | localhost | ok
2025-11-05 00:16:35.373804 | 
2025-11-05 00:16:35.373884 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-05 00:16:35.853724 | localhost | changed
2025-11-05 00:16:35.864205 | 
2025-11-05 00:16:35.864306 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-05 00:16:35.903236 | localhost | ok
2025-11-05 00:16:35.911342 | 
2025-11-05 00:16:35.911408 | TASK [Set zuul-log-path fact]
2025-11-05 00:16:35.942587 | localhost | ok
2025-11-05 00:16:35.967577 | 
2025-11-05 00:16:35.967769 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-05 00:16:35.998987 | localhost | ok
2025-11-05 00:16:36.010112 | 
2025-11-05 00:16:36.010178 | LOOP [Run upload-logs-swift role]
2025-11-05 00:16:36.046580 | localhost | Output suppressed because no_log was given
2025-11-05 00:16:36.075810 | 
2025-11-05 00:16:36.075933 | TASK [Set zuul-log-path fact]
2025-11-05 00:16:36.101113 | localhost | skipping: Conditional result was False
2025-11-05 00:16:36.108927 | 
2025-11-05 00:16:36.109021 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-05 00:16:36.542051 | localhost -> localhost | ok: Runtime: 0:00:00.009164
2025-11-05 00:16:36.547862 | 
2025-11-05 00:16:36.547932 | TASK [upload-logs-swift : Upload logs to swift]