2025-09-19 00:12:24.038674 | Job console starting...
2025-09-19 00:12:24.049392 | Updating repositories
2025-09-19 00:12:24.194410 | Preparing job workspace
2025-09-19 00:12:27.878949 | Running Ansible setup...
2025-09-19 00:12:34.205969 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-19 00:12:34.825928 | 
2025-09-19 00:12:34.826078 | PLAY [localhost]
2025-09-19 00:12:34.834785 | 
2025-09-19 00:12:34.834879 | TASK [Gathering Facts]
2025-09-19 00:12:35.816882 | localhost | ok
2025-09-19 00:12:35.838437 | 
2025-09-19 00:12:35.839167 | TASK [Setup log path fact]
2025-09-19 00:12:35.859307 | localhost | ok
2025-09-19 00:12:35.877407 | 
2025-09-19 00:12:35.877670 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-19 00:12:35.905314 | localhost | ok
2025-09-19 00:12:35.913887 | 
2025-09-19 00:12:35.914005 | TASK [emit-job-header : Print job information]
2025-09-19 00:12:35.962092 | # Job Information
2025-09-19 00:12:35.962223 | Ansible Version: 2.15.12
2025-09-19 00:12:35.962255 | Job: ansible-test-sanity-docker-milestone
2025-09-19 00:12:35.962276 | Pipeline: periodic
2025-09-19 00:12:35.962295 | Executor: ze01.softwarefactory-project.io
2025-09-19 00:12:35.962313 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-19 00:12:35.962334 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/5c8/ansible/5c82334b9da545f6998c0d9b99b26036/
2025-09-19 00:12:35.962354 | Event ID: 64473e9b3ea44517a8ad3ee6b629d0ae
2025-09-19 00:12:35.966048 | 
2025-09-19 00:12:35.966111 | LOOP [emit-job-header : Print node information]
2025-09-19 00:12:36.072884 | localhost | ok:
2025-09-19 00:12:36.073128 | localhost | # Node Information
2025-09-19 00:12:36.073157 | localhost | Inventory Hostname: controller
2025-09-19 00:12:36.073177 | localhost | Hostname: ip-172-16-255-220
2025-09-19 00:12:36.073196 | localhost | Username: zuul-worker
2025-09-19 00:12:36.073217 | localhost | Distro: Fedora 37
2025-09-19 00:12:36.073236 | localhost | Provider: ansible-us-east-2
2025-09-19 00:12:36.073254 | localhost | Region: us-east-2
2025-09-19 00:12:36.073272 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-19 00:12:36.073289 | localhost | Product Name: t3.small
2025-09-19 00:12:36.073306 | localhost | Interface IP: 3.143.210.14
2025-09-19 00:12:36.088420 | 
2025-09-19 00:12:36.088549 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-19 00:12:36.606399 | localhost -> localhost | changed
2025-09-19 00:12:36.614329 | 
2025-09-19 00:12:36.614429 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-19 00:12:37.545724 | localhost -> localhost | changed
2025-09-19 00:12:37.591891 | 
2025-09-19 00:12:37.592099 | PLAY [all:!appliance*]
2025-09-19 00:12:37.621512 | 
2025-09-19 00:12:37.621636 | TASK [include_role : start-zuul-console]
2025-09-19 00:12:37.642331 | controller | ok
2025-09-19 00:12:37.663210 | 
2025-09-19 00:12:37.663339 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-19 00:12:38.302377 | controller | ok
2025-09-19 00:12:38.323804 | 
2025-09-19 00:12:38.323936 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-19 00:12:39.752894 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-19 00:12:39.766266 | 
2025-09-19 00:12:39.766400 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-19 00:12:39.920246 | controller | skipping: Conditional result was False
2025-09-19 00:12:39.929154 | 
2025-09-19 00:12:39.929284 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-19 00:12:39.955069 | controller | skipping: Conditional result was False
2025-09-19 00:12:39.967744 | 
2025-09-19 00:12:39.967930 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-19 00:12:40.005097 | controller | skipping: Conditional result was False
2025-09-19 00:12:40.017329 | 
2025-09-19 00:12:40.017473 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-19 00:12:40.044197 | controller | skipping: Conditional result was False
2025-09-19 00:12:40.057174 | 
2025-09-19 00:12:40.057351 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-19 00:12:40.083842 | controller | skipping: Conditional result was False
2025-09-19 00:12:40.096213 | 
2025-09-19 00:12:40.096353 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-19 00:12:40.122714 | controller | skipping: Conditional result was False
2025-09-19 00:12:40.148185 | 
2025-09-19 00:12:40.148341 | TASK [Disable Fedora Modular]
2025-09-19 00:12:40.824709 | controller | changed
2025-09-19 00:12:40.831870 | 
2025-09-19 00:12:40.831957 | TASK [Enable EPEL]
2025-09-19 00:12:40.858045 | controller | skipping: Conditional result was False
2025-09-19 00:12:40.866364 | 
2025-09-19 00:12:40.866481 | TASK [Register the RHEL node]
2025-09-19 00:12:41.024371 | 
2025-09-19 00:12:41.024643 | TASK [Show the subscription-manager status]
2025-09-19 00:12:41.179422 | controller | skipping: Conditional result was False
2025-09-19 00:12:41.233272 | 
2025-09-19 00:12:41.233439 | TASK [Enable EPEL on RHEL]
2025-09-19 00:12:41.363368 | controller | skipping: Conditional result was False
2025-09-19 00:12:41.376337 | 
2025-09-19 00:12:41.376477 | TASK [Install git and tox]
2025-09-19 00:14:15.222949 | controller | changed
2025-09-19 00:14:15.240108 | 
2025-09-19 00:14:15.240316 | TASK [include_role : prepare-workspace]
2025-09-19 00:14:15.269187 | controller | ok
2025-09-19 00:14:15.305449 | 
2025-09-19 00:14:15.305623 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-19 00:14:15.856978 | controller | ok
2025-09-19 00:14:15.870307 | 
2025-09-19 00:14:15.870437 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-19 00:14:29.233302 | controller | Output suppressed because no_log was given
2025-09-19 00:14:29.246550 | 
2025-09-19 00:14:29.246618 | TASK [include_role : prepare-workspace-openshift]
2025-09-19 00:14:29.277481 | controller | skipping: Conditional result was False
2025-09-19 00:14:29.303831 | 
2025-09-19 00:14:29.303935 | PLAY [all:!appliance]
2025-09-19 00:14:29.323508 | 
2025-09-19 00:14:29.323635 | TASK [Run add-build-sshkey role (RSA)]
2025-09-19 00:14:29.354390 | controller | ok
2025-09-19 00:14:29.369207 | 
2025-09-19 00:14:29.369285 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-19 00:14:29.659402 | controller -> localhost | ok
2025-09-19 00:14:29.667127 | 
2025-09-19 00:14:29.667229 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-19 00:14:29.788734 | controller | ok
2025-09-19 00:14:29.806885 | controller | included: /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-19 00:14:29.812890 | 
2025-09-19 00:14:29.812972 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-19 00:14:30.327911 | controller -> localhost | Generating public/private rsa key pair.
2025-09-19 00:14:30.328305 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/work/5c82334b9da545f6998c0d9b99b26036_id_rsa.
2025-09-19 00:14:30.328374 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/work/5c82334b9da545f6998c0d9b99b26036_id_rsa.pub.
2025-09-19 00:14:30.328421 | controller -> localhost | The key fingerprint is:
2025-09-19 00:14:30.328465 | controller -> localhost | SHA256:bt5U6DJDTJc5h8D+0zm+pLz5fkvIbjtAVhMMq5LtliM zuul-build-sshkey
2025-09-19 00:14:30.328511 | controller -> localhost | The key's randomart image is:
2025-09-19 00:14:30.328554 | controller -> localhost | +---[RSA 2048]----+
2025-09-19 00:14:30.328627 | controller -> localhost | |       .. .o..   |
2025-09-19 00:14:30.328678 | controller -> localhost | |        .. =+    |
2025-09-19 00:14:30.328721 | controller -> localhost | |       .. B...   |
2025-09-19 00:14:30.328764 | controller -> localhost | |       =.oo+     |
2025-09-19 00:14:30.328831 | controller -> localhost | |      o S+....   |
2025-09-19 00:14:30.328890 | controller -> localhost | |       = o+o+.   |
2025-09-19 00:14:30.328944 | controller -> localhost | |      E @ o++..  |
2025-09-19 00:14:30.328996 | controller -> localhost | |       = O =+..  |
2025-09-19 00:14:30.329137 | controller -> localhost | |        . *=*=.. |
2025-09-19 00:14:30.329197 | controller -> localhost | +----[SHA256]-----+
2025-09-19 00:14:30.329293 | controller -> localhost | ok: Runtime: 0:00:00.123530
2025-09-19 00:14:30.343841 | 
2025-09-19 00:14:30.344085 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-19 00:14:30.379520 | controller | ok
2025-09-19 00:14:30.395338 | controller | included: /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-19 00:14:30.409208 | 
2025-09-19 00:14:30.409341 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-19 00:14:30.434934 | controller | skipping: Conditional result was False
2025-09-19 00:14:30.447997 | 
2025-09-19 00:14:30.448205 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-19 00:14:31.091451 | controller | changed
2025-09-19 00:14:31.104964 | 
2025-09-19 00:14:31.105168 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-19 00:14:31.456708 | controller | ok
2025-09-19 00:14:31.462749 | 
2025-09-19 00:14:31.462816 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-19 00:14:32.733701 | controller | changed
2025-09-19 00:14:32.745899 | 
2025-09-19 00:14:32.746078 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-19 00:14:34.032279 | controller | changed
2025-09-19 00:14:34.044769 | 
2025-09-19 00:14:34.044917 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-19 00:14:34.072607 | controller | skipping: Conditional result was False
2025-09-19 00:14:34.099557 | 
2025-09-19 00:14:34.099733 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-19 00:14:34.548309 | controller -> localhost | changed
2025-09-19 00:14:34.568546 | 
2025-09-19 00:14:34.568696 | TASK [add-build-sshkey : Add back temp key]
2025-09-19 00:14:34.839002 | controller -> localhost | Identity added: /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/work/5c82334b9da545f6998c0d9b99b26036_id_rsa (zuul-build-sshkey)
2025-09-19 00:14:34.839432 | controller -> localhost | ok: Runtime: 0:00:00.015308
2025-09-19 00:14:34.855456 | 
2025-09-19 00:14:34.855594 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-19 00:14:35.319905 | controller | ok
2025-09-19 00:14:35.327747 | 
2025-09-19 00:14:35.327884 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-19 00:14:35.352942 | controller | skipping: Conditional result was False
2025-09-19 00:14:35.364253 | 
2025-09-19 00:14:35.364371 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-19 00:14:35.385752 | controller | ok
2025-09-19 00:14:35.403315 | 
2025-09-19 00:14:35.403441 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-19 00:14:35.621415 | controller -> localhost | ok
2025-09-19 00:14:35.630082 | 
2025-09-19 00:14:35.630189 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-19 00:14:35.651801 | controller | ok
2025-09-19 00:14:35.662915 | controller | included: /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-19 00:14:35.669730 | 
2025-09-19 00:14:35.669820 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-19 00:14:35.950735 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-19 00:14:35.951077 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/work/5c82334b9da545f6998c0d9b99b26036_id_ecdsa.
2025-09-19 00:14:35.951146 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/work/5c82334b9da545f6998c0d9b99b26036_id_ecdsa.pub.
2025-09-19 00:14:35.951209 | controller -> localhost | The key fingerprint is:
2025-09-19 00:14:35.951254 | controller -> localhost | SHA256:Jca1CGWCtK7OD/R2tWfP9+FFuhTvTm4/D4oFO369+HM zuul-build-sshkey
2025-09-19 00:14:35.951301 | controller -> localhost | The key's randomart image is:
2025-09-19 00:14:35.951342 | controller -> localhost | +---[ECDSA 521]---+
2025-09-19 00:14:35.951381 | controller -> localhost | |   ...o.o .      |
2025-09-19 00:14:35.951420 | controller -> localhost | |    .. = o .     |
2025-09-19 00:14:35.951459 | controller -> localhost | |    .   = o      |
2025-09-19 00:14:35.951497 | controller -> localhost | |   .   . o       |
2025-09-19 00:14:35.951534 | controller -> localhost | |  . .   S .   . .|
2025-09-19 00:14:35.951573 | controller -> localhost | | . o   . . o   = |
2025-09-19 00:14:35.951611 | controller -> localhost | |  o o . . = ..+.+|
2025-09-19 00:14:35.951649 | controller -> localhost | | o o .   + *.+=BE|
2025-09-19 00:14:35.951688 | controller -> localhost | |  o..     o.=o+O@|
2025-09-19 00:14:35.951726 | controller -> localhost | +----[SHA256]-----+
2025-09-19 00:14:35.951817 | controller -> localhost | ok: Runtime: 0:00:00.010515
2025-09-19 00:14:35.966006 | 
2025-09-19 00:14:35.966198 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-19 00:14:35.991845 | controller | ok
2025-09-19 00:14:36.001959 | controller | included: /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-19 00:14:36.014127 | 
2025-09-19 00:14:36.014214 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-19 00:14:36.039592 | controller | skipping: Conditional result was False
2025-09-19 00:14:36.047870 | 
2025-09-19 00:14:36.047955 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-19 00:14:36.513519 | controller | changed
2025-09-19 00:14:36.521879 | 
2025-09-19 00:14:36.522084 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-19 00:14:36.865310 | controller | ok
2025-09-19 00:14:36.874322 | 
2025-09-19 00:14:36.874473 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-19 00:14:38.163095 | controller | changed
2025-09-19 00:14:38.175490 | 
2025-09-19 00:14:38.175643 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-19 00:14:39.435847 | controller | changed
2025-09-19 00:14:39.443034 | 
2025-09-19 00:14:39.443141 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-19 00:14:39.479633 | controller | skipping: Conditional result was False
2025-09-19 00:14:39.489479 | 
2025-09-19 00:14:39.489606 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-19 00:14:39.836715 | controller -> localhost | changed
2025-09-19 00:14:39.867112 | 
2025-09-19 00:14:39.867277 | TASK [add-build-sshkey : Add back temp key]
2025-09-19 00:14:40.221313 | controller -> localhost | Identity added: /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/work/5c82334b9da545f6998c0d9b99b26036_id_ecdsa (zuul-build-sshkey)
2025-09-19 00:14:40.221683 | controller -> localhost | ok: Runtime: 0:00:00.009279
2025-09-19 00:14:40.237147 | 
2025-09-19 00:14:40.237294 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-19 00:14:40.583946 | controller | ok
2025-09-19 00:14:40.597535 | 
2025-09-19 00:14:40.597672 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-19 00:14:40.636390 | controller | skipping: Conditional result was False
2025-09-19 00:14:40.665189 | 
2025-09-19 00:14:40.665329 | TASK [include_role : remove-zuul-sshkey]
2025-09-19 00:14:40.692667 | controller | skipping: Conditional result was False
2025-09-19 00:14:40.702489 | 
2025-09-19 00:14:40.702604 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-19 00:14:41.029612 | controller | ok: "logs"
2025-09-19 00:14:41.029871 | controller | ok: All items complete
2025-09-19 00:14:41.029899 | 
2025-09-19 00:14:41.794421 | controller | ok: "artifacts"
2025-09-19 00:14:42.086546 | controller | ok: "docs"
2025-09-19 00:14:42.149872 | 
2025-09-19 00:14:42.150037 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-19 00:14:42.497206 | controller | changed: "logs"
2025-09-19 00:14:42.781797 | controller | changed: "artifacts"
2025-09-19 00:14:43.073402 | controller | changed: "docs"
2025-09-19 00:14:43.131301 | 
2025-09-19 00:14:43.131429 | PLAY RECAP
2025-09-19 00:14:43.131489 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-19 00:14:43.131530 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-19 00:14:43.131557 | 
2025-09-19 00:14:43.254989 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-19 00:14:43.255907 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-19 00:14:43.837956 | 
2025-09-19 00:14:43.838116 | PLAY [all]
2025-09-19 00:14:43.863231 | 
2025-09-19 00:14:43.863376 | TASK [Install binary dependencies]
2025-09-19 00:14:43.938656 | controller | ok
2025-09-19 00:14:43.969781 | 
2025-09-19 00:14:43.970011 | TASK [bindep : Include find tasks]
2025-09-19 00:14:44.014686 | controller | ok
2025-09-19 00:14:44.026624 | controller | included: /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-19 00:14:44.035469 | 
2025-09-19 00:14:44.035598 | TASK [bindep : Look for bindep.txt]
2025-09-19 00:14:44.575053 | controller | ok
2025-09-19 00:14:44.592550 | 
2025-09-19 00:14:44.592855 | TASK [bindep : Define bindep_file fact]
2025-09-19 00:14:44.622244 | controller | skipping: Conditional result was False
2025-09-19 00:14:44.631603 | 
2025-09-19 00:14:44.631735 | TASK [bindep : Look for other-requirements.txt]
2025-09-19 00:14:44.930442 | controller | ok
2025-09-19 00:14:44.938214 | 
2025-09-19 00:14:44.938366 | TASK [bindep : Define bindep_file fact]
2025-09-19 00:14:44.964203 | controller | skipping: Conditional result was False
2025-09-19 00:14:44.972804 | 
2025-09-19 00:14:44.972924 | TASK [bindep : Look for bindep fallback file]
2025-09-19 00:14:44.998091 | controller | skipping: Conditional result was False
2025-09-19 00:14:45.007561 | 
2025-09-19 00:14:45.007832 | TASK [bindep : Define bindep_file fact]
2025-09-19 00:14:45.032940 | controller | skipping: Conditional result was False
2025-09-19 00:14:45.042638 | 
2025-09-19 00:14:45.042777 | TASK [bindep : Include bindep tasks]
2025-09-19 00:14:45.068091 | controller | skipping: Conditional result was False
2025-09-19 00:14:45.076740 | 
2025-09-19 00:14:45.076893 | TASK [bindep : Include install tasks]
2025-09-19 00:14:45.101480 | controller | skipping: Conditional result was False
2025-09-19 00:14:45.110877 | 
2025-09-19 00:14:45.111000 | LOOP [bindep : Include package tasks]
2025-09-19 00:14:45.167418 | 
2025-09-19 00:14:45.167591 | TASK [Run test-setup role]
2025-09-19 00:14:45.186440 | controller | ok
2025-09-19 00:14:45.205210 | 
2025-09-19 00:14:45.205336 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-19 00:14:45.525570 | controller | ok
2025-09-19 00:14:45.535118 | 
2025-09-19 00:14:45.535255 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-19 00:14:45.678115 | controller | skipping: Conditional result was False
2025-09-19 00:14:45.713506 | 
2025-09-19 00:14:45.713646 | PLAY RECAP
2025-09-19 00:14:45.713700 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-19 00:14:45.713729 | 
2025-09-19 00:14:45.842805 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-19 00:14:45.844294 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-19 00:14:46.472476 | 
2025-09-19 00:14:46.472621 | PLAY [controller]
2025-09-19 00:14:46.494734 | 
2025-09-19 00:14:46.494883 | TASK [Create the /root directory]
2025-09-19 00:14:47.246401 | controller | ok
2025-09-19 00:14:47.264390 | 
2025-09-19 00:14:47.264577 | TASK [Install glibc-langpack-en]
2025-09-19 00:14:55.379914 | controller | ok: Nothing to do
2025-09-19 00:14:55.392939 | 
2025-09-19 00:14:55.393150 | TASK [Ensure controller directory exists]
2025-09-19 00:14:55.847964 | controller | changed
2025-09-19 00:14:55.855237 | 
2025-09-19 00:14:55.855325 | TASK [Install container runtime]
2025-09-19 00:14:55.928957 | controller | ok
2025-09-19 00:14:55.975574 | 
2025-09-19 00:14:55.975699 | LOOP [ensure-podman : Find distribution installation]
2025-09-19 00:14:56.010084 | controller | ok: "/var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-19 00:14:56.022294 | controller | included: /var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-19 00:14:56.028793 | 
2025-09-19 00:14:56.028866 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-19 00:16:17.151663 | controller | changed
2025-09-19 00:16:17.164069 | 
2025-09-19 00:16:17.164274 | TASK [ensure-podman : Fetch podman version]
2025-09-19 00:16:17.893725 | controller | Client:       Podman Engine
2025-09-19 00:16:17.893826 | controller | Version:      4.6.2
2025-09-19 00:16:17.893858 | controller | API Version:  4.6.2
2025-09-19 00:16:17.893885 | controller | Go Version:   go1.19.12
2025-09-19 00:16:17.893923 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-19 00:16:17.893951 | controller | OS/Arch:      linux/amd64
2025-09-19 00:16:18.309166 | controller | ok: Runtime: 0:00:00.218562
2025-09-19 00:16:18.324896 | 
2025-09-19 00:16:18.325236 | TASK [ensure-podman : Print podman version installed]
2025-09-19 00:16:18.368573 | Podman version: Client:       Podman Engine
2025-09-19 00:16:18.369170 | Version:      4.6.2
2025-09-19 00:16:18.369247 | API Version:  4.6.2
2025-09-19 00:16:18.369297 | Go Version:   go1.19.12
2025-09-19 00:16:18.369340 | Built:        Mon Aug 28 19:38:31 2023
2025-09-19 00:16:18.369388 | OS/Arch:      linux/amd64
2025-09-19 00:16:18.382059 | 
2025-09-19 00:16:18.382194 | TASK [ensure-podman : Validate podman engine]
2025-09-19 00:16:18.521281 | controller | skipping: Conditional result was False
2025-09-19 00:16:18.535292 | 
2025-09-19 00:16:18.535440 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-19 00:16:18.552893 | controller | skipping: Conditional result was False
2025-09-19 00:16:18.578673 | 
2025-09-19 00:16:18.578827 | TASK [Ensure python3.8 is present]
2025-09-19 00:16:18.605196 | controller | skipping: Conditional result was False
2025-09-19 00:16:18.614607 | 
2025-09-19 00:16:18.614693 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-19 00:16:18.634988 | controller | ok
2025-09-19 00:16:18.661934 | 
2025-09-19 00:16:18.662141 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-19 00:16:22.382065 | controller | ok: Nothing to do
2025-09-19 00:16:22.389652 | 
2025-09-19 00:16:22.389719 | TASK [our-ensure-python : Also install python3-devel]
2025-09-19 00:16:35.537733 | controller | changed
2025-09-19 00:16:35.552835 | 
2025-09-19 00:16:35.552986 | TASK [Run ensure-virtualenv role]
2025-09-19 00:16:35.574919 | controller | ok
2025-09-19 00:16:35.603682 | 
2025-09-19 00:16:35.603830 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-19 00:16:35.997598 | controller | /usr/bin/virtualenv
2025-09-19 00:16:36.236162 | controller | ok: Runtime: 0:00:00.012816
2025-09-19 00:16:36.244667 | 
2025-09-19 00:16:36.244753 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-19 00:16:36.273317 | controller | skipping: Conditional result was False
2025-09-19 00:16:36.273601 | controller | ok: All items complete
2025-09-19 00:16:36.273659 | 
2025-09-19 00:16:36.305892 | 
2025-09-19 00:16:36.306176 | TASK [Find the full path of the Python interpreter]
2025-09-19 00:16:36.788454 | controller | /usr/bin/python3
2025-09-19 00:16:36.979114 | controller | ok
2025-09-19 00:16:36.987158 | 
2025-09-19 00:16:36.987260 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-19 00:16:38.420427 | controller | created virtual environment CPython3.11.0.final.0-64 in 772ms
2025-09-19 00:16:38.462891 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-19 00:16:38.462947 | 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-09-19 00:16:38.462965 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-19 00:16:38.462988 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-19 00:16:38.634302 | controller | changed
2025-09-19 00:16:38.643766 | 
2025-09-19 00:16:38.643907 | TASK [Set selinux package]
2025-09-19 00:16:38.682531 | controller | ok
2025-09-19 00:16:38.694424 | 
2025-09-19 00:16:38.694564 | TASK [Set selinux package (Fedora)]
2025-09-19 00:16:38.732143 | controller | ok
2025-09-19 00:16:38.743375 | 
2025-09-19 00:16:38.743520 | TASK [Install selinux into virtualenv]
2025-09-19 00:16:41.394947 | controller | Collecting selinux-please-lie-to-me
2025-09-19 00:16:41.482472 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-19 00:16:42.018315 | controller | Collecting setuptools<50.0.0
2025-09-19 00:16:42.032325 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-19 00:16:42.152974 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.1 MB/s eta 0:00:00
2025-09-19 00:16:42.313610 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-19 00:16:42.313942 | controller |   Attempting uninstall: setuptools
2025-09-19 00:16:42.318911 | controller |     Found existing installation: setuptools 62.6.0
2025-09-19 00:16:42.431552 | controller |     Uninstalling setuptools-62.6.0:
2025-09-19 00:16:42.446855 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-19 00:16:43.212136 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-19 00:16:43.425179 | controller |
2025-09-19 00:16:43.639381 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-19 00:16:43.639434 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-19 00:16:43.911750 | controller | ok: Runtime: 0:00:04.426631
2025-09-19 00:16:43.918597 | 
2025-09-19 00:16:43.918696 | TASK [Install pytest-forked into virtualenv]
2025-09-19 00:16:45.133406 | controller | Collecting pytest-forked
2025-09-19 00:16:45.219317 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-19 00:16:45.279094 | controller | Collecting py
2025-09-19 00:16:45.291365 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-19 00:16:45.329014 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00
2025-09-19 00:16:45.506047 | controller | Collecting pytest>=3.10
2025-09-19 00:16:45.534597 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-19 00:16:45.594448 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.4 MB/s eta 0:00:00
2025-09-19 00:16:45.650103 | controller | Collecting iniconfig>=1
2025-09-19 00:16:45.662288 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-19 00:16:45.729366 | controller | Collecting packaging>=20
2025-09-19 00:16:45.741480 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-19 00:16:45.753648 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.7 MB/s eta 0:00:00
2025-09-19 00:16:45.801880 | controller | Collecting pluggy<2,>=1.5
2025-09-19 00:16:45.814684 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-19 00:16:45.888996 | controller | Collecting pygments>=2.7.2
2025-09-19 00:16:45.904454 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-19 00:16:46.024113 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.5 MB/s eta 0:00:00
2025-09-19 00:16:46.155494 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-19 00:16:48.406897 | 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-09-19 00:16:48.423965 | controller |
2025-09-19 00:16:48.598092 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-19 00:16:48.598138 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-19 00:16:49.082572 | controller | ok: Runtime: 0:00:04.196256
2025-09-19 00:16:49.088424 | 
2025-09-19 00:16:49.088549 | TASK [Update pip]
2025-09-19 00:16:50.137120 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-19 00:16:50.386911 | controller | Collecting pip
2025-09-19 00:16:50.484462 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-19 00:16:50.645965 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.1 MB/s eta 0:00:00
2025-09-19 00:16:50.811510 | controller | Installing collected packages: pip
2025-09-19 00:16:50.813070 | controller |   Attempting uninstall: pip
2025-09-19 00:16:50.818151 | controller |     Found existing installation: pip 22.2.2
2025-09-19 00:16:51.145935 | controller |     Uninstalling pip-22.2.2:
2025-09-19 00:16:51.189724 | controller |       Successfully uninstalled pip-22.2.2
2025-09-19 00:16:52.888161 | controller | Successfully installed pip-25.2
2025-09-19 00:16:53.218156 | controller | ok: Runtime: 0:00:03.576796
2025-09-19 00:16:53.224230 | 
2025-09-19 00:16:53.224313 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-19 00:16:53.756853 | controller | changed
2025-09-19 00:16:53.762864 | 
2025-09-19 00:16:53.762936 | TASK [Install ansible into virtualenv]
2025-09-19 00:16:54.803531 | controller | Processing ./src/github.com/ansible/ansible
2025-09-19 00:16:54.810215 | controller |   Installing build dependencies: started
2025-09-19 00:16:56.704096 | controller |   Installing build dependencies: finished with status 'done'
2025-09-19 00:16:58.236812 | controller |   Getting requirements to build wheel: started
2025-09-19 00:16:58.236879 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-19 00:16:59.143818 | controller |   Preparing metadata (pyproject.toml): started
2025-09-19 00:16:59.143877 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-19 00:16:59.148715 | 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-09-19 00:16:59.153486 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-19 00:16:59.399487 | controller | ERROR
2025-09-19 00:16:59.399652 | controller | {
2025-09-19 00:16:59.399681 | controller |   "delta": "0:00:05.121965",
2025-09-19 00:16:59.399701 | controller |   "end": "2025-09-19 00:16:59.298026",
2025-09-19 00:16:59.399720 | controller |   "msg": "non-zero return code",
2025-09-19 00:16:59.399748 | controller |   "rc": 1,
2025-09-19 00:16:59.399766 | controller |   "start": "2025-09-19 00:16:54.176061"
2025-09-19 00:16:59.399783 | controller | }
failure
2025-09-19 00:16:59.401453 | 
2025-09-19 00:16:59.401498 | PLAY RECAP
2025-09-19 00:16:59.401541 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-19 00:16:59.401563 | 
2025-09-19 00:16:59.507098 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-19 00:16:59.508116 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-19 00:17:00.189997 | 
2025-09-19 00:17:00.190143 | PLAY [all]
2025-09-19 00:17:00.211792 | 
2025-09-19 00:17:00.211915 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-19 00:17:00.987117 | controller | changed: non-zero return code
2025-09-19 00:17:00.999970 | 
2025-09-19 00:17:01.000174 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-19 00:17:01.027278 | controller | skipping: Conditional result was False
2025-09-19 00:17:01.040218 | 
2025-09-19 00:17:01.040379 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-19 00:17:01.075759 | 
2025-09-19 00:17:01.075975 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-19 00:17:01.109972 | 
2025-09-19 00:17:01.110206 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-19 00:17:01.125734 | controller | skipping: Conditional result was False
2025-09-19 00:17:01.142585 | 
2025-09-19 00:17:01.142780 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-19 00:17:01.168200 | 
2025-09-19 00:17:01.168369 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-19 00:17:01.192917 | controller | skipping: Conditional result was False
2025-09-19 00:17:01.200894 | 
2025-09-19 00:17:01.200991 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-19 00:17:01.215570 | controller | skipping: Conditional result was False
2025-09-19 00:17:01.224077 | 
2025-09-19 00:17:01.224171 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-19 00:17:01.248753 | controller | skipping: Conditional result was False
2025-09-19 00:17:01.289278 | 
2025-09-19 00:17:01.289388 | PLAY RECAP
2025-09-19 00:17:01.289437 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-19 00:17:01.289464 | 
2025-09-19 00:17:01.385072 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-19 00:17:01.386906 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-19 00:17:02.021405 | 
2025-09-19 00:17:02.021521 | PLAY [all:!appliance*]
2025-09-19 00:17:02.042042 | 
2025-09-19 00:17:02.042141 | TASK [unregister the node]
2025-09-19 00:17:02.170594 | controller | skipping: Conditional result was False
2025-09-19 00:17:02.183587 | 
2025-09-19 00:17:02.183766 | TASK [include_role : fetch-output]
2025-09-19 00:17:02.222959 | controller | ok
2025-09-19 00:17:02.258868 | 
2025-09-19 00:17:02.258981 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-19 00:17:02.315190 | controller | skipping: Conditional result was False
2025-09-19 00:17:02.327317 | 
2025-09-19 00:17:02.327457 | TASK [fetch-output : Set log path for single node]
2025-09-19 00:17:02.371744 | controller | ok
2025-09-19 00:17:02.379407 | 
2025-09-19 00:17:02.379502 | LOOP [fetch-output : Ensure local output dirs]
2025-09-19 00:17:02.814947 | controller -> localhost | ok: "/var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/work/logs"
2025-09-19 00:17:03.070549 | controller -> localhost | changed: "/var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/work/artifacts"
2025-09-19 00:17:03.327483 | controller -> localhost | changed: "/var/lib/zuul/builds/5c82334b9da545f6998c0d9b99b26036/work/docs"
2025-09-19 00:17:03.338756 | 
2025-09-19 00:17:03.338849 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-19 00:17:04.484204 | controller | changed:
2025-09-19 00:17:04.484567 | controller | .d..t...... ./
2025-09-19 00:17:04.484629 | controller | cd+++++++++ controller/
2025-09-19 00:17:04.484701 | controller | changed: All items complete
2025-09-19 00:17:04.484744 | 
2025-09-19 00:17:05.545878 | controller | changed: .d..t...... ./
2025-09-19 00:17:06.584482 | controller | changed: .d..t...... ./
2025-09-19 00:17:06.605917 | 
2025-09-19 00:17:06.606066 | TASK [include_role : fetch-output-openshift]
2025-09-19 00:17:06.641238 | controller | skipping: Conditional result was False
2025-09-19 00:17:06.649669 | 
2025-09-19 00:17:06.649764 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-19 00:17:06.690264 | controller | skipping: Conditional result was False
2025-09-19 00:17:06.702500 | controller | skipping: Conditional result was False
2025-09-19 00:17:06.732593 | 
2025-09-19 00:17:06.732713 | PLAY [localhost]
2025-09-19 00:17:06.745309 | 
2025-09-19 00:17:06.745387 | TASK [Run Zuul manifest role]
2025-09-19 00:17:06.763983 | localhost | ok
2025-09-19 00:17:06.777262 | 
2025-09-19 00:17:06.777330 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-19 00:17:07.184606 | localhost | changed
2025-09-19 00:17:07.189646 | 
2025-09-19 00:17:07.189747 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-19 00:17:07.220656 | localhost | ok
2025-09-19 00:17:07.228789 | 
2025-09-19 00:17:07.228864 | TASK [Set zuul-log-path fact]
2025-09-19 00:17:07.248197 | localhost | ok
2025-09-19 00:17:07.261467 | 
2025-09-19 00:17:07.261558 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-19 00:17:07.293258 | localhost | ok
2025-09-19 00:17:07.306904 | 
2025-09-19 00:17:07.307045 | LOOP [Run upload-logs-swift role]
2025-09-19 00:17:07.333081 | localhost | Output suppressed because no_log was given
2025-09-19 00:17:07.358807 | 
2025-09-19 00:17:07.358954 | TASK [Set zuul-log-path fact]
2025-09-19 00:17:07.384003 | localhost | skipping: Conditional result was False
2025-09-19 00:17:07.391576 | 
2025-09-19 00:17:07.391725 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-19 00:17:07.816107 | localhost -> localhost | ok: Runtime: 0:00:00.009245
2025-09-19 00:17:07.822299 | 
2025-09-19 00:17:07.822403 | TASK [upload-logs-swift : Upload logs to swift]