2025-09-16 00:17:20.754679 | Job console starting...
2025-09-16 00:17:20.768526 | Updating repositories
2025-09-16 00:17:20.921617 | Preparing job workspace
2025-09-16 00:17:24.553218 | Running Ansible setup...
2025-09-16 00:17:32.521265 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-16 00:17:33.101625 | 
2025-09-16 00:17:33.101766 | PLAY [localhost]
2025-09-16 00:17:33.110631 | 
2025-09-16 00:17:33.110706 | TASK [Gathering Facts]
2025-09-16 00:17:34.137253 | localhost | ok
2025-09-16 00:17:34.166627 | 
2025-09-16 00:17:34.166827 | TASK [Setup log path fact]
2025-09-16 00:17:34.187839 | localhost | ok
2025-09-16 00:17:34.206084 | 
2025-09-16 00:17:34.206207 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-16 00:17:34.227120 | localhost | ok
2025-09-16 00:17:34.238574 | 
2025-09-16 00:17:34.238677 | TASK [emit-job-header : Print job information]
2025-09-16 00:17:34.269217 | # Job Information
2025-09-16 00:17:34.269408 | Ansible Version: 2.15.12
2025-09-16 00:17:34.269452 | Job: ansible-test-sanity-docker-milestone
2025-09-16 00:17:34.269482 | Pipeline: periodic
2025-09-16 00:17:34.269508 | Executor: ze03.softwarefactory-project.io
2025-09-16 00:17:34.269534 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-16 00:17:34.269564 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/b22/ansible/b22a7ed8a56548559ccc38995ef1971c/
2025-09-16 00:17:34.269590 | Event ID: 2918163660474a46b98b92e6629b114f
2025-09-16 00:17:34.274978 | 
2025-09-16 00:17:34.275066 | LOOP [emit-job-header : Print node information]
2025-09-16 00:17:34.369159 | localhost | ok:
2025-09-16 00:17:34.369358 | localhost | # Node Information
2025-09-16 00:17:34.369386 | localhost | Inventory Hostname: controller
2025-09-16 00:17:34.369406 | localhost | Hostname: np0005433283
2025-09-16 00:17:34.369424 | localhost | Username: zuul
2025-09-16 00:17:34.369465 | localhost | Distro: Fedora 37
2025-09-16 00:17:34.369485 | localhost | Provider: ansible-vexxhost-ams1
2025-09-16 00:17:34.369502 | localhost | Region: ams1
2025-09-16 00:17:34.369518 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-16 00:17:34.369534 | localhost | Product Name: OpenStack Nova
2025-09-16 00:17:34.369550 | localhost | Interface IP: 38.129.16.162
2025-09-16 00:17:34.382635 | 
2025-09-16 00:17:34.382797 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-16 00:17:34.757237 | localhost -> localhost | changed
2025-09-16 00:17:34.764714 | 
2025-09-16 00:17:34.764878 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-16 00:17:35.595526 | localhost -> localhost | changed
2025-09-16 00:17:35.637296 | 
2025-09-16 00:17:35.637393 | PLAY [all:!appliance*]
2025-09-16 00:17:35.660186 | 
2025-09-16 00:17:35.660275 | TASK [include_role : start-zuul-console]
2025-09-16 00:17:35.687213 | controller | ok
2025-09-16 00:17:35.711008 | 
2025-09-16 00:17:35.711122 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-16 00:17:36.804709 | controller | ok
2025-09-16 00:17:36.834602 | 
2025-09-16 00:17:36.834867 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-16 00:17:39.962516 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-16 00:17:39.982507 | 
2025-09-16 00:17:39.982835 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-16 00:17:40.361759 | controller | skipping: Conditional result was False
2025-09-16 00:17:40.377495 | 
2025-09-16 00:17:40.377705 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-16 00:17:40.414097 | controller | skipping: Conditional result was False
2025-09-16 00:17:40.423557 | 
2025-09-16 00:17:40.423718 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-16 00:17:40.459581 | controller | skipping: Conditional result was False
2025-09-16 00:17:40.473965 | 
2025-09-16 00:17:40.474214 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-16 00:17:40.503458 | controller | skipping: Conditional result was False
2025-09-16 00:17:40.517865 | 
2025-09-16 00:17:40.518271 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-16 00:17:40.545545 | controller | skipping: Conditional result was False
2025-09-16 00:17:40.559812 | 
2025-09-16 00:17:40.559953 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-16 00:17:40.587083 | controller | skipping: Conditional result was False
2025-09-16 00:17:40.615006 | 
2025-09-16 00:17:40.615139 | TASK [Disable Fedora Modular]
2025-09-16 00:17:41.750236 | controller | changed
2025-09-16 00:17:41.758689 | 
2025-09-16 00:17:41.758806 | TASK [Enable EPEL]
2025-09-16 00:17:41.783991 | controller | skipping: Conditional result was False
2025-09-16 00:17:41.792311 | 
2025-09-16 00:17:41.792402 | TASK [Register the RHEL node]
2025-09-16 00:17:42.204170 | 
2025-09-16 00:17:42.204448 | TASK [Show the subscription-manager status]
2025-09-16 00:17:42.588217 | controller | skipping: Conditional result was False
2025-09-16 00:17:42.598534 | 
2025-09-16 00:17:42.598653 | TASK [Enable EPEL on RHEL]
2025-09-16 00:17:42.994892 | controller | skipping: Conditional result was False
2025-09-16 00:17:43.011626 | 
2025-09-16 00:17:43.011828 | TASK [Install git and tox]
2025-09-16 00:19:39.840158 | controller | changed
2025-09-16 00:19:39.855197 | 
2025-09-16 00:19:39.855347 | TASK [include_role : prepare-workspace]
2025-09-16 00:19:39.902251 | controller | ok
2025-09-16 00:19:39.933572 | 
2025-09-16 00:19:39.933703 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-16 00:19:40.863690 | controller | ok
2025-09-16 00:19:40.869975 | 
2025-09-16 00:19:40.870043 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-16 00:19:56.389761 | controller | Output suppressed because no_log was given
2025-09-16 00:19:56.406321 | 
2025-09-16 00:19:56.406428 | TASK [include_role : prepare-workspace-openshift]
2025-09-16 00:19:56.432899 | controller | skipping: Conditional result was False
2025-09-16 00:19:56.465025 | 
2025-09-16 00:19:56.465111 | PLAY [all:!appliance]
2025-09-16 00:19:56.487371 | 
2025-09-16 00:19:56.487438 | TASK [Run add-build-sshkey role (RSA)]
2025-09-16 00:19:56.518886 | controller | ok
2025-09-16 00:19:56.533995 | 
2025-09-16 00:19:56.534059 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-16 00:19:56.805269 | controller -> localhost | ok
2025-09-16 00:19:56.820167 | 
2025-09-16 00:19:56.820310 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-16 00:19:56.864383 | controller | ok
2025-09-16 00:19:56.899827 | controller | included: /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-16 00:19:56.908591 | 
2025-09-16 00:19:56.908680 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-16 00:19:57.403332 | controller -> localhost | Generating public/private rsa key pair.
2025-09-16 00:19:57.403586 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/work/b22a7ed8a56548559ccc38995ef1971c_id_rsa.
2025-09-16 00:19:57.403629 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/work/b22a7ed8a56548559ccc38995ef1971c_id_rsa.pub.
2025-09-16 00:19:57.403659 | controller -> localhost | The key fingerprint is:
2025-09-16 00:19:57.403685 | controller -> localhost | SHA256:0CKXbVoXsG8H6aKpzeQkPoQinNU7q+PvUUlNkBV9O2w zuul-build-sshkey
2025-09-16 00:19:57.403711 | controller -> localhost | The key's randomart image is:
2025-09-16 00:19:57.403784 | controller -> localhost | +---[RSA 2048]----+
2025-09-16 00:19:57.403812 | controller -> localhost | |       .==+      |
2025-09-16 00:19:57.403839 | controller -> localhost | |       =o. + .   |
2025-09-16 00:19:57.403866 | controller -> localhost | |    o =.*.+ o .  |
2025-09-16 00:19:57.403891 | controller -> localhost | |   . +.*.+ . E   |
2025-09-16 00:19:57.403914 | controller -> localhost | |. o.  ooS + o .  |
2025-09-16 00:19:57.403950 | controller -> localhost | |oo. .o.o o .     |
2025-09-16 00:19:57.403981 | controller -> localhost | |.. ...B          |
2025-09-16 00:19:57.404007 | controller -> localhost | |   o.X.          |
2025-09-16 00:19:57.404032 | controller -> localhost | |  .oB++          |
2025-09-16 00:19:57.404061 | controller -> localhost | +----[SHA256]-----+
2025-09-16 00:19:57.404127 | controller -> localhost | ok: Runtime: 0:00:00.048568
2025-09-16 00:19:57.413104 | 
2025-09-16 00:19:57.413185 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-16 00:19:57.435705 | controller | ok
2025-09-16 00:19:57.448541 | controller | included: /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-16 00:19:57.461319 | 
2025-09-16 00:19:57.461406 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-16 00:19:57.476112 | controller | skipping: Conditional result was False
2025-09-16 00:19:57.484812 | 
2025-09-16 00:19:57.484898 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-16 00:19:58.604619 | controller | changed
2025-09-16 00:19:58.617785 | 
2025-09-16 00:19:58.617954 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-16 00:19:59.328250 | controller | ok
2025-09-16 00:19:59.336103 | 
2025-09-16 00:19:59.336208 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-16 00:20:02.425405 | controller | changed
2025-09-16 00:20:02.434249 | 
2025-09-16 00:20:02.434356 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-16 00:20:05.433103 | controller | changed
2025-09-16 00:20:05.445451 | 
2025-09-16 00:20:05.445586 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-16 00:20:05.472175 | controller | skipping: Conditional result was False
2025-09-16 00:20:05.486517 | 
2025-09-16 00:20:05.486679 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-16 00:20:05.963150 | controller -> localhost | changed
2025-09-16 00:20:05.988361 | 
2025-09-16 00:20:05.988549 | TASK [add-build-sshkey : Add back temp key]
2025-09-16 00:20:06.372998 | controller -> localhost | Identity added: /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/work/b22a7ed8a56548559ccc38995ef1971c_id_rsa (zuul-build-sshkey)
2025-09-16 00:20:06.373406 | controller -> localhost | ok: Runtime: 0:00:00.013533
2025-09-16 00:20:06.388232 | 
2025-09-16 00:20:06.388365 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-16 00:20:07.326447 | controller | ok
2025-09-16 00:20:07.338135 | 
2025-09-16 00:20:07.338279 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-16 00:20:07.375832 | controller | skipping: Conditional result was False
2025-09-16 00:20:07.401489 | 
2025-09-16 00:20:07.401661 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-16 00:20:07.440713 | controller | ok
2025-09-16 00:20:07.476199 | 
2025-09-16 00:20:07.476369 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-16 00:20:07.780552 | controller -> localhost | ok
2025-09-16 00:20:07.797274 | 
2025-09-16 00:20:07.797432 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-16 00:20:07.837207 | controller | ok
2025-09-16 00:20:07.859581 | controller | included: /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-16 00:20:07.867882 | 
2025-09-16 00:20:07.867981 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-16 00:20:08.190879 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-16 00:20:08.191238 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/work/b22a7ed8a56548559ccc38995ef1971c_id_ecdsa.
2025-09-16 00:20:08.191320 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/work/b22a7ed8a56548559ccc38995ef1971c_id_ecdsa.pub.
2025-09-16 00:20:08.191441 | controller -> localhost | The key fingerprint is:
2025-09-16 00:20:08.191506 | controller -> localhost | SHA256:Ha7REoSOAXRCcOJ4QcW+q+XU/gMlBOrtiLUThIn1rmE zuul-build-sshkey
2025-09-16 00:20:08.191564 | controller -> localhost | The key's randomart image is:
2025-09-16 00:20:08.191619 | controller -> localhost | +---[ECDSA 521]---+
2025-09-16 00:20:08.191675 | controller -> localhost | |o=X++. ..        |
2025-09-16 00:20:08.191726 | controller -> localhost | |+* *o o.         |
2025-09-16 00:20:08.191839 | controller -> localhost | |=.+..=  . .      |
2025-09-16 00:20:08.191893 | controller -> localhost | | + oo o .= .     |
2025-09-16 00:20:08.191943 | controller -> localhost | |  E o. oS +      |
2025-09-16 00:20:08.191983 | controller -> localhost | | + B...  +       |
2025-09-16 00:20:08.192021 | controller -> localhost | |. = +....        |
2025-09-16 00:20:08.192059 | controller -> localhost | |   =..  .        |
2025-09-16 00:20:08.192096 | controller -> localhost | |  ... ....       |
2025-09-16 00:20:08.192133 | controller -> localhost | +----[SHA256]-----+
2025-09-16 00:20:08.192219 | controller -> localhost | ok: Runtime: 0:00:00.014507
2025-09-16 00:20:08.207239 | 
2025-09-16 00:20:08.207397 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-16 00:20:08.236887 | controller | ok
2025-09-16 00:20:08.290262 | controller | included: /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-16 00:20:08.300340 | 
2025-09-16 00:20:08.300414 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-16 00:20:08.324469 | controller | skipping: Conditional result was False
2025-09-16 00:20:08.331859 | 
2025-09-16 00:20:08.331928 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-16 00:20:09.288120 | controller | changed
2025-09-16 00:20:09.301205 | 
2025-09-16 00:20:09.301353 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-16 00:20:09.958958 | controller | ok
2025-09-16 00:20:09.968252 | 
2025-09-16 00:20:09.968349 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-16 00:20:13.020019 | controller | changed
2025-09-16 00:20:13.032503 | 
2025-09-16 00:20:13.032638 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-16 00:20:16.026793 | controller | changed
2025-09-16 00:20:16.041516 | 
2025-09-16 00:20:16.041815 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-16 00:20:16.070944 | controller | skipping: Conditional result was False
2025-09-16 00:20:16.084707 | 
2025-09-16 00:20:16.084979 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-16 00:20:16.367893 | controller -> localhost | changed
2025-09-16 00:20:16.380305 | 
2025-09-16 00:20:16.380375 | TASK [add-build-sshkey : Add back temp key]
2025-09-16 00:20:16.689419 | controller -> localhost | Identity added: /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/work/b22a7ed8a56548559ccc38995ef1971c_id_ecdsa (zuul-build-sshkey)
2025-09-16 00:20:16.689650 | controller -> localhost | ok: Runtime: 0:00:00.013380
2025-09-16 00:20:16.696191 | 
2025-09-16 00:20:16.696252 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-16 00:20:17.381375 | controller | ok
2025-09-16 00:20:17.399651 | 
2025-09-16 00:20:17.399855 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-16 00:20:17.436172 | controller | skipping: Conditional result was False
2025-09-16 00:20:17.456963 | 
2025-09-16 00:20:17.457073 | TASK [include_role : remove-zuul-sshkey]
2025-09-16 00:20:17.482467 | controller | skipping: Conditional result was False
2025-09-16 00:20:17.493489 | 
2025-09-16 00:20:17.493584 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-16 00:20:18.161317 | controller | ok: "logs"
2025-09-16 00:20:18.161619 | controller | ok: All items complete
2025-09-16 00:20:18.161664 | 
2025-09-16 00:20:18.760143 | controller | ok: "artifacts"
2025-09-16 00:20:19.392440 | controller | ok: "docs"
2025-09-16 00:20:19.416109 | 
2025-09-16 00:20:19.416814 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-16 00:20:20.089711 | controller | changed: "logs"
2025-09-16 00:20:20.730598 | controller | changed: "artifacts"
2025-09-16 00:20:21.333651 | controller | changed: "docs"
2025-09-16 00:20:21.385117 | 
2025-09-16 00:20:21.385237 | PLAY RECAP
2025-09-16 00:20:21.385297 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-16 00:20:21.385333 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-16 00:20:21.385360 | 
2025-09-16 00:20:21.522189 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-16 00:20:21.523055 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-16 00:20:22.155011 | 
2025-09-16 00:20:22.155139 | PLAY [all]
2025-09-16 00:20:22.180094 | 
2025-09-16 00:20:22.180230 | TASK [Install binary dependencies]
2025-09-16 00:20:22.241254 | controller | ok
2025-09-16 00:20:22.262044 | 
2025-09-16 00:20:22.262153 | TASK [bindep : Include find tasks]
2025-09-16 00:20:22.292141 | controller | ok
2025-09-16 00:20:22.299776 | controller | included: /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-16 00:20:22.306619 | 
2025-09-16 00:20:22.306700 | TASK [bindep : Look for bindep.txt]
2025-09-16 00:20:23.226613 | controller | ok
2025-09-16 00:20:23.245627 | 
2025-09-16 00:20:23.245878 | TASK [bindep : Define bindep_file fact]
2025-09-16 00:20:23.273700 | controller | skipping: Conditional result was False
2025-09-16 00:20:23.287773 | 
2025-09-16 00:20:23.288068 | TASK [bindep : Look for other-requirements.txt]
2025-09-16 00:20:23.918045 | controller | ok
2025-09-16 00:20:23.931437 | 
2025-09-16 00:20:23.931584 | TASK [bindep : Define bindep_file fact]
2025-09-16 00:20:23.968520 | controller | skipping: Conditional result was False
2025-09-16 00:20:23.982102 | 
2025-09-16 00:20:23.982243 | TASK [bindep : Look for bindep fallback file]
2025-09-16 00:20:24.025223 | controller | skipping: Conditional result was False
2025-09-16 00:20:24.040883 | 
2025-09-16 00:20:24.041049 | TASK [bindep : Define bindep_file fact]
2025-09-16 00:20:24.068342 | controller | skipping: Conditional result was False
2025-09-16 00:20:24.078363 | 
2025-09-16 00:20:24.078456 | TASK [bindep : Include bindep tasks]
2025-09-16 00:20:24.104629 | controller | skipping: Conditional result was False
2025-09-16 00:20:24.114208 | 
2025-09-16 00:20:24.114301 | TASK [bindep : Include install tasks]
2025-09-16 00:20:24.138747 | controller | skipping: Conditional result was False
2025-09-16 00:20:24.149566 | 
2025-09-16 00:20:24.149674 | LOOP [bindep : Include package tasks]
2025-09-16 00:20:24.215989 | 
2025-09-16 00:20:24.216153 | TASK [Run test-setup role]
2025-09-16 00:20:24.234502 | controller | ok
2025-09-16 00:20:24.250966 | 
2025-09-16 00:20:24.251037 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-16 00:20:24.936058 | controller | ok
2025-09-16 00:20:24.948915 | 
2025-09-16 00:20:24.949056 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-16 00:20:25.317594 | controller | skipping: Conditional result was False
2025-09-16 00:20:25.373232 | 
2025-09-16 00:20:25.373364 | PLAY RECAP
2025-09-16 00:20:25.373440 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-16 00:20:25.373488 | 
2025-09-16 00:20:25.490687 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-16 00:20:25.492928 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-16 00:20:26.157793 | 
2025-09-16 00:20:26.157928 | PLAY [controller]
2025-09-16 00:20:26.178266 | 
2025-09-16 00:20:26.178360 | TASK [Create the /root directory]
2025-09-16 00:20:27.212556 | controller | ok
2025-09-16 00:20:27.226454 | 
2025-09-16 00:20:27.226718 | TASK [Install glibc-langpack-en]
2025-09-16 00:20:34.857220 | controller | ok: Nothing to do
2025-09-16 00:20:34.863354 | 
2025-09-16 00:20:34.863454 | TASK [Ensure controller directory exists]
2025-09-16 00:20:35.668506 | controller | changed
2025-09-16 00:20:35.680923 | 
2025-09-16 00:20:35.681065 | TASK [Install container runtime]
2025-09-16 00:20:35.756113 | controller | ok
2025-09-16 00:20:35.803139 | 
2025-09-16 00:20:35.803277 | LOOP [ensure-podman : Find distribution installation]
2025-09-16 00:20:35.842014 | controller | ok: "/var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-16 00:20:35.855417 | controller | included: /var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-16 00:20:35.862032 | 
2025-09-16 00:20:35.862099 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-16 00:22:28.765620 | controller | changed
2025-09-16 00:22:28.779631 | 
2025-09-16 00:22:28.779752 | TASK [ensure-podman : Fetch podman version]
2025-09-16 00:22:29.930653 | controller | Client:       Podman Engine
2025-09-16 00:22:29.930772 | controller | Version:      4.6.2
2025-09-16 00:22:29.930816 | controller | API Version:  4.6.2
2025-09-16 00:22:29.930857 | controller | Go Version:   go1.19.12
2025-09-16 00:22:29.930913 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-16 00:22:29.930955 | controller | OS/Arch:      linux/amd64
2025-09-16 00:22:30.148337 | controller | ok: Runtime: 0:00:00.264960
2025-09-16 00:22:30.155224 | 
2025-09-16 00:22:30.155292 | TASK [ensure-podman : Print podman version installed]
2025-09-16 00:22:30.185143 | Podman version: Client:       Podman Engine
2025-09-16 00:22:30.185258 | Version:      4.6.2
2025-09-16 00:22:30.185286 | API Version:  4.6.2
2025-09-16 00:22:30.185307 | Go Version:   go1.19.12
2025-09-16 00:22:30.185325 | Built:        Mon Aug 28 19:38:31 2023
2025-09-16 00:22:30.185344 | OS/Arch:      linux/amd64
2025-09-16 00:22:30.191930 | 
2025-09-16 00:22:30.191989 | TASK [ensure-podman : Validate podman engine]
2025-09-16 00:22:30.545130 | controller | skipping: Conditional result was False
2025-09-16 00:22:30.560115 | 
2025-09-16 00:22:30.560831 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-16 00:22:30.591588 | controller | skipping: Conditional result was False
2025-09-16 00:22:30.602628 | 
2025-09-16 00:22:30.602707 | TASK [Ensure python3.8 is present]
2025-09-16 00:22:30.616394 | controller | skipping: Conditional result was False
2025-09-16 00:22:30.622135 | 
2025-09-16 00:22:30.622198 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-16 00:22:30.640851 | controller | ok
2025-09-16 00:22:30.664681 | 
2025-09-16 00:22:30.664787 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-16 00:22:34.207256 | controller | ok: Nothing to do
2025-09-16 00:22:34.220143 | 
2025-09-16 00:22:34.220282 | TASK [our-ensure-python : Also install python3-devel]
2025-09-16 00:22:47.934753 | controller | changed
2025-09-16 00:22:47.958907 | 
2025-09-16 00:22:47.959067 | TASK [Run ensure-virtualenv role]
2025-09-16 00:22:47.991379 | controller | ok
2025-09-16 00:22:48.028714 | 
2025-09-16 00:22:48.028893 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-16 00:22:49.013183 | controller | /usr/bin/virtualenv
2025-09-16 00:22:49.391415 | controller | ok: Runtime: 0:00:00.007298
2025-09-16 00:22:49.404545 | 
2025-09-16 00:22:49.404707 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-16 00:22:49.440982 | controller | skipping: Conditional result was False
2025-09-16 00:22:49.441253 | controller | ok: All items complete
2025-09-16 00:22:49.441280 | 
2025-09-16 00:22:49.468564 | 
2025-09-16 00:22:49.468802 | TASK [Find the full path of the Python interpreter]
2025-09-16 00:22:50.358077 | controller | /usr/bin/python3
2025-09-16 00:22:50.866148 | controller | ok
2025-09-16 00:22:50.878808 | 
2025-09-16 00:22:50.878972 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-16 00:22:52.752367 | controller | created virtual environment CPython3.11.0.final.0-64 in 796ms
2025-09-16 00:22:52.808750 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-16 00:22:52.809370 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv)
2025-09-16 00:22:52.809385 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-16 00:22:52.809405 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-16 00:22:53.262875 | controller | changed
2025-09-16 00:22:53.276951 | 
2025-09-16 00:22:53.277091 | TASK [Set selinux package]
2025-09-16 00:22:53.312216 | controller | ok
2025-09-16 00:22:53.318555 | 
2025-09-16 00:22:53.318623 | TASK [Set selinux package (Fedora)]
2025-09-16 00:22:53.349699 | controller | ok
2025-09-16 00:22:53.356077 | 
2025-09-16 00:22:53.356158 | TASK [Install selinux into virtualenv]
2025-09-16 00:22:56.215223 | controller | Collecting selinux-please-lie-to-me
2025-09-16 00:22:56.277104 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-16 00:22:56.734861 | controller | Collecting setuptools<50.0.0
2025-09-16 00:22:56.740094 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-16 00:22:56.787764 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 20.6 MB/s eta 0:00:00
2025-09-16 00:22:56.915338 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-16 00:22:56.915607 | controller |   Attempting uninstall: setuptools
2025-09-16 00:22:56.919224 | controller |     Found existing installation: setuptools 62.6.0
2025-09-16 00:22:57.014216 | controller |     Uninstalling setuptools-62.6.0:
2025-09-16 00:22:57.028857 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-16 00:22:57.688442 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-16 00:22:57.862017 | controller |
2025-09-16 00:22:58.105633 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-16 00:22:58.105664 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-16 00:22:58.239701 | controller | ok: Runtime: 0:00:03.902951
2025-09-16 00:22:58.246129 | 
2025-09-16 00:22:58.246250 | TASK [Install pytest-forked into virtualenv]
2025-09-16 00:22:59.725571 | controller | Collecting pytest-forked
2025-09-16 00:22:59.781303 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-16 00:22:59.827345 | controller | Collecting py
2025-09-16 00:22:59.833174 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-16 00:22:59.863354 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00
2025-09-16 00:23:00.027751 | controller | Collecting pytest>=3.10
2025-09-16 00:23:00.032438 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-16 00:23:00.053509 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 20.8 MB/s eta 0:00:00
2025-09-16 00:23:00.097138 | controller | Collecting iniconfig>=1
2025-09-16 00:23:00.101774 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-16 00:23:00.164801 | controller | Collecting packaging>=20
2025-09-16 00:23:00.170817 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-16 00:23:00.179095 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 11.0 MB/s eta 0:00:00
2025-09-16 00:23:00.224769 | controller | Collecting pluggy<2,>=1.5
2025-09-16 00:23:00.229574 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-16 00:23:00.299818 | controller | Collecting pygments>=2.7.2
2025-09-16 00:23:00.307186 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-16 00:23:00.336592 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 48.9 MB/s eta 0:00:00
2025-09-16 00:23:00.441105 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-16 00:23:02.678321 | 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-16 00:23:02.697537 | controller |
2025-09-16 00:23:02.956752 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-16 00:23:02.956808 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-16 00:23:03.140713 | controller | ok: Runtime: 0:00:03.876465
2025-09-16 00:23:03.153930 | 
2025-09-16 00:23:03.154081 | TASK [Update pip]
2025-09-16 00:23:04.507233 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-16 00:23:04.746011 | controller | Collecting pip
2025-09-16 00:23:04.821918 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-16 00:23:04.899255 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.4 MB/s eta 0:00:00
2025-09-16 00:23:04.992858 | controller | Installing collected packages: pip
2025-09-16 00:23:04.993189 | controller |   Attempting uninstall: pip
2025-09-16 00:23:04.996470 | controller |     Found existing installation: pip 22.2.2
2025-09-16 00:23:05.214126 | controller |     Uninstalling pip-22.2.2:
2025-09-16 00:23:05.237253 | controller |       Successfully uninstalled pip-22.2.2
2025-09-16 00:23:07.054837 | controller | Successfully installed pip-25.2
2025-09-16 00:23:07.536640 | controller | ok: Runtime: 0:00:03.249002
2025-09-16 00:23:07.543533 | 
2025-09-16 00:23:07.543609 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-16 00:23:08.451622 | controller | changed
2025-09-16 00:23:08.464518 | 
2025-09-16 00:23:08.464664 | TASK [Install ansible into virtualenv]
2025-09-16 00:23:09.797508 | controller | Processing ./src/github.com/ansible/ansible
2025-09-16 00:23:09.802316 | controller |   Installing build dependencies: started
2025-09-16 00:23:11.505108 | controller |   Installing build dependencies: finished with status 'done'
2025-09-16 00:23:11.505621 | controller |   Getting requirements to build wheel: started
2025-09-16 00:23:12.991916 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-16 00:23:12.997181 | controller |   Preparing metadata (pyproject.toml): started
2025-09-16 00:23:13.889133 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-16 00:23:13.894477 | 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-16 00:23:13.899701 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-16 00:23:14.349309 | controller | ERROR
2025-09-16 00:23:14.349575 | controller | {
2025-09-16 00:23:14.349628 | controller |   "delta": "0:00:04.813311",
2025-09-16 00:23:14.349657 | controller |   "end": "2025-09-16 00:23:14.079768",
2025-09-16 00:23:14.349686 | controller |   "msg": "non-zero return code",
2025-09-16 00:23:14.349753 | controller |   "rc": 1,
2025-09-16 00:23:14.349788 | controller |   "start": "2025-09-16 00:23:09.266457"
2025-09-16 00:23:14.349813 | controller | }
failure
2025-09-16 00:23:14.351934 | 
2025-09-16 00:23:14.352002 | PLAY RECAP
2025-09-16 00:23:14.352075 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-16 00:23:14.352113 | 
2025-09-16 00:23:14.480096 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-16 00:23:14.482143 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-16 00:23:15.183320 | 
2025-09-16 00:23:15.183443 | PLAY [all]
2025-09-16 00:23:15.205583 | 
2025-09-16 00:23:15.205713 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-16 00:23:17.067038 | controller | changed: non-zero return code
2025-09-16 00:23:17.081197 | 
2025-09-16 00:23:17.081405 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-16 00:23:17.110940 | controller | skipping: Conditional result was False
2025-09-16 00:23:17.125880 | 
2025-09-16 00:23:17.126030 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-16 00:23:17.172486 | 
2025-09-16 00:23:17.172838 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-16 00:23:17.216225 | 
2025-09-16 00:23:17.216483 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-16 00:23:17.243312 | controller | skipping: Conditional result was False
2025-09-16 00:23:17.257126 | 
2025-09-16 00:23:17.257267 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-16 00:23:17.296635 | 
2025-09-16 00:23:17.296928 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-16 00:23:17.323267 | controller | skipping: Conditional result was False
2025-09-16 00:23:17.335978 | 
2025-09-16 00:23:17.336116 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-16 00:23:17.362582 | controller | skipping: Conditional result was False
2025-09-16 00:23:17.375199 | 
2025-09-16 00:23:17.375326 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-16 00:23:17.389862 | controller | skipping: Conditional result was False
2025-09-16 00:23:17.436442 | 
2025-09-16 00:23:17.436566 | PLAY RECAP
2025-09-16 00:23:17.436619 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-16 00:23:17.436648 | 
2025-09-16 00:23:17.547623 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-16 00:23:17.549290 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-16 00:23:18.176161 | 
2025-09-16 00:23:18.176278 | PLAY [all:!appliance*]
2025-09-16 00:23:18.198896 | 
2025-09-16 00:23:18.198979 | TASK [unregister the node]
2025-09-16 00:23:18.551236 | controller | skipping: Conditional result was False
2025-09-16 00:23:18.563983 | 
2025-09-16 00:23:18.564148 | TASK [include_role : fetch-output]
2025-09-16 00:23:18.615251 | controller | ok
2025-09-16 00:23:18.650774 | 
2025-09-16 00:23:18.650909 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-16 00:23:18.727992 | controller | skipping: Conditional result was False
2025-09-16 00:23:18.736300 | 
2025-09-16 00:23:18.736394 | TASK [fetch-output : Set log path for single node]
2025-09-16 00:23:18.778427 | controller | ok
2025-09-16 00:23:18.786645 | 
2025-09-16 00:23:18.786784 | LOOP [fetch-output : Ensure local output dirs]
2025-09-16 00:23:19.197645 | controller -> localhost | ok: "/var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/work/logs"
2025-09-16 00:23:19.458084 | controller -> localhost | changed: "/var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/work/artifacts"
2025-09-16 00:23:19.716990 | controller -> localhost | changed: "/var/lib/zuul/builds/b22a7ed8a56548559ccc38995ef1971c/work/docs"
2025-09-16 00:23:19.735586 | 
2025-09-16 00:23:19.735826 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-16 00:23:21.929772 | controller | changed:
2025-09-16 00:23:21.929965 | controller | .d..t...... ./
2025-09-16 00:23:21.929992 | controller | cd+++++++++ controller/
2025-09-16 00:23:21.930025 | controller | changed: All items complete
2025-09-16 00:23:21.930045 | 
2025-09-16 00:23:24.017699 | controller | changed: .d..t...... ./
2025-09-16 00:23:26.037041 | controller | changed: .d..t...... ./
2025-09-16 00:23:26.061363 | 
2025-09-16 00:23:26.061524 | TASK [include_role : fetch-output-openshift]
2025-09-16 00:23:26.087223 | controller | skipping: Conditional result was False
2025-09-16 00:23:26.117544 | 
2025-09-16 00:23:26.117674 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-16 00:23:26.179984 | controller | skipping: Conditional result was False
2025-09-16 00:23:26.190542 | controller | skipping: Conditional result was False
2025-09-16 00:23:26.241497 | 
2025-09-16 00:23:26.241616 | PLAY [localhost]
2025-09-16 00:23:26.256829 | 
2025-09-16 00:23:26.256942 | TASK [Run Zuul manifest role]
2025-09-16 00:23:26.275562 | localhost | ok
2025-09-16 00:23:26.290051 | 
2025-09-16 00:23:26.290153 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-16 00:23:26.710493 | localhost | changed
2025-09-16 00:23:26.715127 | 
2025-09-16 00:23:26.715190 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-16 00:23:26.743077 | localhost | ok
2025-09-16 00:23:26.751233 | 
2025-09-16 00:23:26.751291 | TASK [Set zuul-log-path fact]
2025-09-16 00:23:26.769594 | localhost | ok
2025-09-16 00:23:26.806488 | 
2025-09-16 00:23:26.806603 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-16 00:23:26.844880 | localhost | ok
2025-09-16 00:23:26.853100 | 
2025-09-16 00:23:26.853161 | LOOP [Run upload-logs-swift role]
2025-09-16 00:23:26.887493 | localhost | Output suppressed because no_log was given
2025-09-16 00:23:26.912289 | 
2025-09-16 00:23:26.912376 | TASK [Set zuul-log-path fact]
2025-09-16 00:23:26.936347 | localhost | skipping: Conditional result was False
2025-09-16 00:23:26.942541 | 
2025-09-16 00:23:26.942608 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-16 00:23:27.414569 | localhost -> localhost | ok: Runtime: 0:00:00.008971
2025-09-16 00:23:27.431986 | 
2025-09-16 00:23:27.432187 | TASK [upload-logs-swift : Upload logs to swift]