2025-12-24 00:26:59.621645 | Job console starting... 2025-12-24 00:26:59.631440 | Updating repositories 2025-12-24 00:26:59.790483 | Preparing job workspace 2025-12-24 00:27:03.111509 | Running Ansible setup... 2025-12-24 00:27:08.234606 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-24 00:27:08.882915 | 2025-12-24 00:27:08.883103 | PLAY [localhost] 2025-12-24 00:27:08.893303 | 2025-12-24 00:27:08.893455 | TASK [Gathering Facts] 2025-12-24 00:27:09.963146 | localhost | ok 2025-12-24 00:27:10.013257 | 2025-12-24 00:27:10.013501 | TASK [Setup log path fact] 2025-12-24 00:27:10.050515 | localhost | ok 2025-12-24 00:27:10.077821 | 2025-12-24 00:27:10.077970 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-24 00:27:10.119105 | localhost | ok 2025-12-24 00:27:10.130810 | 2025-12-24 00:27:10.130940 | TASK [emit-job-header : Print job information] 2025-12-24 00:27:10.191326 | # Job Information 2025-12-24 00:27:10.191596 | Ansible Version: 2.15.12 2025-12-24 00:27:10.191664 | Job: ansible-test-sanity-docker-milestone 2025-12-24 00:27:10.191710 | Pipeline: periodic 2025-12-24 00:27:10.191807 | Executor: ze03.softwarefactory-project.io 2025-12-24 00:27:10.191866 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-24 00:27:10.192111 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/351/ansible/351888a9753b4c799f797a4835da9eb4/ 2025-12-24 00:27:10.192174 | Event ID: 444a083e8b1242a295732fab2106314a 2025-12-24 00:27:10.206380 | 2025-12-24 00:27:10.206583 | LOOP [emit-job-header : Print node information] 2025-12-24 00:27:10.361295 | localhost | ok: 2025-12-24 00:27:10.361550 | localhost | # Node Information 2025-12-24 00:27:10.361587 | localhost | Inventory Hostname: controller 2025-12-24 00:27:10.361617 | localhost | Hostname: np0005569806 2025-12-24 00:27:10.361673 | localhost | Username: zuul 2025-12-24 00:27:10.361786 | localhost | Distro: Fedora 37 2025-12-24 00:27:10.361850 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-24 00:27:10.361922 | localhost | Region: ca-ymq-1 2025-12-24 00:27:10.361954 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-24 00:27:10.361981 | localhost | Product Name: OpenStack Nova 2025-12-24 00:27:10.362015 | localhost | Interface IP: 162.253.55.204 2025-12-24 00:27:10.380006 | 2025-12-24 00:27:10.380177 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-24 00:27:10.789898 | localhost -> localhost | changed 2025-12-24 00:27:10.796279 | 2025-12-24 00:27:10.796384 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-24 00:27:11.762043 | localhost -> localhost | changed 2025-12-24 00:27:11.785203 | 2025-12-24 00:27:11.785319 | PLAY [all:!appliance*] 2025-12-24 00:27:11.807614 | 2025-12-24 00:27:11.807988 | TASK [include_role : start-zuul-console] 2025-12-24 00:27:11.838999 | controller | ok 2025-12-24 00:27:11.854038 | 2025-12-24 00:27:11.854157 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-24 00:27:12.244688 | controller | ok 2025-12-24 00:27:12.258368 | 2025-12-24 00:27:12.258504 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-24 00:27:35.033325 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-24 00:27:35.040261 | 2025-12-24 00:27:35.040324 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-24 00:27:35.583068 | controller | skipping: Conditional result was False 2025-12-24 00:27:35.598639 | 2025-12-24 00:27:35.598860 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-24 00:27:35.648048 | controller | skipping: Conditional result was False 2025-12-24 00:27:35.668664 | 2025-12-24 00:27:35.668868 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-24 00:27:35.697059 | controller | skipping: Conditional result was False 2025-12-24 00:27:35.704935 | 2025-12-24 00:27:35.705049 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-24 00:27:35.732051 | controller | skipping: Conditional result was False 2025-12-24 00:27:35.741242 | 2025-12-24 00:27:35.741390 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-24 00:27:35.769473 | controller | skipping: Conditional result was False 2025-12-24 00:27:35.789096 | 2025-12-24 00:27:35.789271 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-24 00:27:35.828131 | controller | skipping: Conditional result was False 2025-12-24 00:27:35.841032 | 2025-12-24 00:27:35.841145 | TASK [Disable Fedora Modular] 2025-12-24 00:27:36.120216 | controller | changed 2025-12-24 00:27:36.128165 | 2025-12-24 00:27:36.128346 | TASK [Enable EPEL] 2025-12-24 00:27:36.154387 | controller | skipping: Conditional result was False 2025-12-24 00:27:36.161814 | 2025-12-24 00:27:36.161894 | TASK [Register the RHEL node] 2025-12-24 00:27:36.700902 | 2025-12-24 00:27:36.701190 | TASK [Show the subscription-manager status] 2025-12-24 00:27:37.235392 | controller | skipping: Conditional result was False 2025-12-24 00:27:37.253298 | 2025-12-24 00:27:37.253522 | TASK [Enable EPEL on RHEL] 2025-12-24 00:27:37.794178 | controller | skipping: Conditional result was False 2025-12-24 00:27:37.807824 | 2025-12-24 00:27:37.808002 | TASK [Install git and tox] 2025-12-24 00:28:35.724904 | controller | changed 2025-12-24 00:28:35.743450 | 2025-12-24 00:28:35.743677 | TASK [include_role : prepare-workspace] 2025-12-24 00:28:35.769018 | controller | ok 2025-12-24 00:28:35.793715 | 2025-12-24 00:28:35.793861 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-24 00:28:36.047342 | controller | ok 2025-12-24 00:28:36.057016 | 2025-12-24 00:28:36.057144 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-24 00:28:49.891071 | controller | Output suppressed because no_log was given 2025-12-24 00:28:49.908340 | 2025-12-24 00:28:49.908483 | TASK [include_role : prepare-workspace-openshift] 2025-12-24 00:28:49.944477 | controller | skipping: Conditional result was False 2025-12-24 00:28:49.975646 | 2025-12-24 00:28:49.975759 | PLAY [all:!appliance] 2025-12-24 00:28:49.991497 | 2025-12-24 00:28:49.991573 | TASK [Run add-build-sshkey role (RSA)] 2025-12-24 00:28:50.031431 | controller | ok 2025-12-24 00:28:50.049467 | 2025-12-24 00:28:50.049607 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-24 00:28:50.289051 | controller -> localhost | ok 2025-12-24 00:28:50.305256 | 2025-12-24 00:28:50.305443 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-24 00:28:50.347823 | controller | ok 2025-12-24 00:28:50.375401 | controller | included: /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-24 00:28:50.385680 | 2025-12-24 00:28:50.385858 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-24 00:28:50.946225 | controller -> localhost | Generating public/private rsa key pair. 2025-12-24 00:28:50.946410 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/work/351888a9753b4c799f797a4835da9eb4_id_rsa. 2025-12-24 00:28:50.946440 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/work/351888a9753b4c799f797a4835da9eb4_id_rsa.pub. 2025-12-24 00:28:50.946462 | controller -> localhost | The key fingerprint is: 2025-12-24 00:28:50.946482 | controller -> localhost | SHA256:FPg8nWUw8AMMot+jzsLIIUGKpaKw8DUCKKsh9/fUWiQ zuul-build-sshkey 2025-12-24 00:28:50.946502 | controller -> localhost | The key's randomart image is: 2025-12-24 00:28:50.946521 | controller -> localhost | +---[RSA 2048]----+ 2025-12-24 00:28:50.946540 | controller -> localhost | |. . .++.o. | 2025-12-24 00:28:50.946559 | controller -> localhost | |+... .. .+ .o | 2025-12-24 00:28:50.946578 | controller -> localhost | |==. o..o+ | 2025-12-24 00:28:50.946596 | controller -> localhost | |% o.o. .E +. | 2025-12-24 00:28:50.946614 | controller -> localhost | |B* +..o S= | 2025-12-24 00:28:50.946642 | controller -> localhost | |=.. ..... o | 2025-12-24 00:28:50.946665 | controller -> localhost | |oo. .. o o | 2025-12-24 00:28:50.946686 | controller -> localhost | |..oo o | 2025-12-24 00:28:50.946705 | controller -> localhost | | .o | 2025-12-24 00:28:50.946744 | controller -> localhost | +----[SHA256]-----+ 2025-12-24 00:28:50.946794 | controller -> localhost | ok: Runtime: 0:00:00.093823 2025-12-24 00:28:50.957045 | 2025-12-24 00:28:50.957161 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-24 00:28:50.977875 | controller | ok 2025-12-24 00:28:50.988420 | controller | included: /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-24 00:28:50.998349 | 2025-12-24 00:28:50.998456 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-24 00:28:51.012831 | controller | skipping: Conditional result was False 2025-12-24 00:28:51.020297 | 2025-12-24 00:28:51.020469 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-24 00:28:51.466563 | controller | changed 2025-12-24 00:28:51.472554 | 2025-12-24 00:28:51.472694 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-24 00:28:51.708715 | controller | ok 2025-12-24 00:28:51.715104 | 2025-12-24 00:28:51.715181 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-24 00:28:52.429368 | controller | changed 2025-12-24 00:28:52.438695 | 2025-12-24 00:28:52.438829 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-24 00:28:53.105902 | controller | changed 2025-12-24 00:28:53.121274 | 2025-12-24 00:28:53.121430 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-24 00:28:53.146997 | controller | skipping: Conditional result was False 2025-12-24 00:28:53.156753 | 2025-12-24 00:28:53.156858 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-24 00:28:53.554349 | controller -> localhost | changed 2025-12-24 00:28:53.570837 | 2025-12-24 00:28:53.570969 | TASK [add-build-sshkey : Add back temp key] 2025-12-24 00:28:53.873086 | controller -> localhost | Identity added: /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/work/351888a9753b4c799f797a4835da9eb4_id_rsa (zuul-build-sshkey) 2025-12-24 00:28:53.873464 | controller -> localhost | ok: Runtime: 0:00:00.009694 2025-12-24 00:28:53.883198 | 2025-12-24 00:28:53.883353 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-24 00:28:54.207350 | controller | ok 2025-12-24 00:28:54.213344 | 2025-12-24 00:28:54.213454 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-24 00:28:54.248220 | controller | skipping: Conditional result was False 2025-12-24 00:28:54.263630 | 2025-12-24 00:28:54.263753 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-24 00:28:54.305622 | controller | ok 2025-12-24 00:28:54.326519 | 2025-12-24 00:28:54.326680 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-24 00:28:54.588461 | controller -> localhost | ok 2025-12-24 00:28:54.597938 | 2025-12-24 00:28:54.598066 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-24 00:28:54.619230 | controller | ok 2025-12-24 00:28:54.630381 | controller | included: /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-24 00:28:54.636926 | 2025-12-24 00:28:54.637020 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-24 00:28:54.936561 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-24 00:28:54.937801 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/work/351888a9753b4c799f797a4835da9eb4_id_ecdsa. 2025-12-24 00:28:54.937845 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/work/351888a9753b4c799f797a4835da9eb4_id_ecdsa.pub. 2025-12-24 00:28:54.937876 | controller -> localhost | The key fingerprint is: 2025-12-24 00:28:54.937897 | controller -> localhost | SHA256:TGYKUJZOPeas8sjx57YLPnNyM62BTW2uGzIiESuJZGI zuul-build-sshkey 2025-12-24 00:28:54.937916 | controller -> localhost | The key's randomart image is: 2025-12-24 00:28:54.937934 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-24 00:28:54.937952 | controller -> localhost | | ..oo | 2025-12-24 00:28:54.937969 | controller -> localhost | | oo + | 2025-12-24 00:28:54.937986 | controller -> localhost | |oE o.+ .+ | 2025-12-24 00:28:54.938003 | controller -> localhost | |*+ ..oB | 2025-12-24 00:28:54.938020 | controller -> localhost | |* .o S | 2025-12-24 00:28:54.938036 | controller -> localhost | |..o .+ o | 2025-12-24 00:28:54.938053 | controller -> localhost | |...*= +.. | 2025-12-24 00:28:54.938070 | controller -> localhost | | .oo*+B+. | 2025-12-24 00:28:54.938087 | controller -> localhost | | .XBB | 2025-12-24 00:28:54.938103 | controller -> localhost | +----[SHA256]-----+ 2025-12-24 00:28:54.938154 | controller -> localhost | ok: Runtime: 0:00:00.008035 2025-12-24 00:28:54.946392 | 2025-12-24 00:28:54.946467 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-24 00:28:54.979377 | controller | ok 2025-12-24 00:28:54.992986 | controller | included: /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-24 00:28:55.009044 | 2025-12-24 00:28:55.009207 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-24 00:28:55.034818 | controller | skipping: Conditional result was False 2025-12-24 00:28:55.043480 | 2025-12-24 00:28:55.043614 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-24 00:28:55.316265 | controller | changed 2025-12-24 00:28:55.325924 | 2025-12-24 00:28:55.326068 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-24 00:28:55.565409 | controller | ok 2025-12-24 00:28:55.577767 | 2025-12-24 00:28:55.578133 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-24 00:28:56.219204 | controller | changed 2025-12-24 00:28:56.234103 | 2025-12-24 00:28:56.234237 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-24 00:28:56.875412 | controller | changed 2025-12-24 00:28:56.893321 | 2025-12-24 00:28:56.893928 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-24 00:28:56.925702 | controller | skipping: Conditional result was False 2025-12-24 00:28:56.935399 | 2025-12-24 00:28:56.935555 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-24 00:28:57.207611 | controller -> localhost | changed 2025-12-24 00:28:57.219262 | 2025-12-24 00:28:57.219357 | TASK [add-build-sshkey : Add back temp key] 2025-12-24 00:28:57.482662 | controller -> localhost | Identity added: /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/work/351888a9753b4c799f797a4835da9eb4_id_ecdsa (zuul-build-sshkey) 2025-12-24 00:28:57.483294 | controller -> localhost | ok: Runtime: 0:00:00.007794 2025-12-24 00:28:57.504571 | 2025-12-24 00:28:57.504881 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-24 00:28:57.713765 | controller | ok 2025-12-24 00:28:57.728418 | 2025-12-24 00:28:57.728640 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-24 00:28:57.767491 | controller | skipping: Conditional result was False 2025-12-24 00:28:57.799362 | 2025-12-24 00:28:57.799557 | TASK [include_role : remove-zuul-sshkey] 2025-12-24 00:28:57.825577 | controller | skipping: Conditional result was False 2025-12-24 00:28:57.835956 | 2025-12-24 00:28:57.836472 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-24 00:28:58.072458 | controller | ok: "logs" 2025-12-24 00:28:58.072735 | controller | ok: All items complete 2025-12-24 00:28:58.072782 | 2025-12-24 00:28:58.285279 | controller | ok: "artifacts" 2025-12-24 00:28:58.482318 | controller | ok: "docs" 2025-12-24 00:28:58.509541 | 2025-12-24 00:28:58.509782 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-24 00:28:58.789397 | controller | changed: "logs" 2025-12-24 00:28:59.024175 | controller | changed: "artifacts" 2025-12-24 00:28:59.223823 | controller | changed: "docs" 2025-12-24 00:28:59.275894 | 2025-12-24 00:28:59.276026 | PLAY RECAP 2025-12-24 00:28:59.276089 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-24 00:28:59.276125 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-24 00:28:59.276151 | 2025-12-24 00:28:59.419174 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-24 00:28:59.421152 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-24 00:29:00.117315 | 2025-12-24 00:29:00.117442 | PLAY [all] 2025-12-24 00:29:00.141975 | 2025-12-24 00:29:00.142087 | TASK [Install binary dependencies] 2025-12-24 00:29:00.192254 | controller | ok 2025-12-24 00:29:00.212515 | 2025-12-24 00:29:00.212654 | TASK [bindep : Include find tasks] 2025-12-24 00:29:00.242592 | controller | ok 2025-12-24 00:29:00.250623 | controller | included: /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-24 00:29:00.257292 | 2025-12-24 00:29:00.257358 | TASK [bindep : Look for bindep.txt] 2025-12-24 00:29:00.627367 | controller | ok 2025-12-24 00:29:00.633370 | 2025-12-24 00:29:00.633442 | TASK [bindep : Define bindep_file fact] 2025-12-24 00:29:00.657839 | controller | skipping: Conditional result was False 2025-12-24 00:29:00.664399 | 2025-12-24 00:29:00.664512 | TASK [bindep : Look for other-requirements.txt] 2025-12-24 00:29:00.892442 | controller | ok 2025-12-24 00:29:00.900891 | 2025-12-24 00:29:00.901036 | TASK [bindep : Define bindep_file fact] 2025-12-24 00:29:00.936308 | controller | skipping: Conditional result was False 2025-12-24 00:29:00.945187 | 2025-12-24 00:29:00.945318 | TASK [bindep : Look for bindep fallback file] 2025-12-24 00:29:00.981059 | controller | skipping: Conditional result was False 2025-12-24 00:29:01.002452 | 2025-12-24 00:29:01.002615 | TASK [bindep : Define bindep_file fact] 2025-12-24 00:29:01.027319 | controller | skipping: Conditional result was False 2025-12-24 00:29:01.035660 | 2025-12-24 00:29:01.035801 | TASK [bindep : Include bindep tasks] 2025-12-24 00:29:01.060901 | controller | skipping: Conditional result was False 2025-12-24 00:29:01.069691 | 2025-12-24 00:29:01.069859 | TASK [bindep : Include install tasks] 2025-12-24 00:29:01.094812 | controller | skipping: Conditional result was False 2025-12-24 00:29:01.101920 | 2025-12-24 00:29:01.102009 | LOOP [bindep : Include package tasks] 2025-12-24 00:29:01.160295 | 2025-12-24 00:29:01.160527 | TASK [Run test-setup role] 2025-12-24 00:29:01.183501 | controller | ok 2025-12-24 00:29:01.206086 | 2025-12-24 00:29:01.206225 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-24 00:29:01.422380 | controller | ok 2025-12-24 00:29:01.429857 | 2025-12-24 00:29:01.429973 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-24 00:29:01.967263 | controller | skipping: Conditional result was False 2025-12-24 00:29:02.001504 | 2025-12-24 00:29:02.001677 | PLAY RECAP 2025-12-24 00:29:02.001764 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-24 00:29:02.001805 | 2025-12-24 00:29:02.129383 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-24 00:29:02.131038 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-24 00:29:02.812445 | 2025-12-24 00:29:02.812630 | PLAY [controller] 2025-12-24 00:29:02.834863 | 2025-12-24 00:29:02.834997 | TASK [Create the /root directory] 2025-12-24 00:29:03.249581 | controller | ok 2025-12-24 00:29:03.270682 | 2025-12-24 00:29:03.270916 | TASK [Install glibc-langpack-en] 2025-12-24 00:29:07.289380 | controller | ok: Nothing to do 2025-12-24 00:29:07.303129 | 2025-12-24 00:29:07.303272 | TASK [Ensure controller directory exists] 2025-12-24 00:29:07.535516 | controller | changed 2025-12-24 00:29:07.545113 | 2025-12-24 00:29:07.545219 | TASK [Install container runtime] 2025-12-24 00:29:07.620236 | controller | ok 2025-12-24 00:29:07.656213 | 2025-12-24 00:29:07.656345 | LOOP [ensure-podman : Find distribution installation] 2025-12-24 00:29:07.684966 | controller | ok: "/var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-24 00:29:07.699920 | controller | included: /var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-24 00:29:07.707021 | 2025-12-24 00:29:07.707133 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-24 00:30:15.138062 | controller | changed 2025-12-24 00:30:15.149878 | 2025-12-24 00:30:15.150003 | TASK [ensure-podman : Fetch podman version] 2025-12-24 00:30:15.655104 | controller | Client: Podman Engine 2025-12-24 00:30:15.655212 | controller | Version: 4.6.2 2025-12-24 00:30:15.655261 | controller | API Version: 4.6.2 2025-12-24 00:30:15.655306 | controller | Go Version: go1.19.12 2025-12-24 00:30:15.655360 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-24 00:30:15.655406 | controller | OS/Arch: linux/amd64 2025-12-24 00:30:15.722421 | controller | ok: Runtime: 0:00:00.171810 2025-12-24 00:30:15.732079 | 2025-12-24 00:30:15.732225 | TASK [ensure-podman : Print podman version installed] 2025-12-24 00:30:15.753757 | Podman version: Client: Podman Engine 2025-12-24 00:30:15.754026 | Version: 4.6.2 2025-12-24 00:30:15.754082 | API Version: 4.6.2 2025-12-24 00:30:15.754104 | Go Version: go1.19.12 2025-12-24 00:30:15.754123 | Built: Mon Aug 28 19:38:31 2023 2025-12-24 00:30:15.754142 | OS/Arch: linux/amd64 2025-12-24 00:30:15.761912 | 2025-12-24 00:30:15.762052 | TASK [ensure-podman : Validate podman engine] 2025-12-24 00:30:16.297267 | controller | skipping: Conditional result was False 2025-12-24 00:30:16.311512 | 2025-12-24 00:30:16.311690 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-24 00:30:16.329009 | controller | skipping: Conditional result was False 2025-12-24 00:30:16.347048 | 2025-12-24 00:30:16.347223 | TASK [Ensure python3.8 is present] 2025-12-24 00:30:16.362167 | controller | skipping: Conditional result was False 2025-12-24 00:30:16.372340 | 2025-12-24 00:30:16.372462 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-24 00:30:16.395693 | controller | ok 2025-12-24 00:30:16.426293 | 2025-12-24 00:30:16.426506 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-24 00:30:17.859545 | controller | ok: Nothing to do 2025-12-24 00:30:17.867998 | 2025-12-24 00:30:17.868092 | TASK [our-ensure-python : Also install python3-devel] 2025-12-24 00:30:26.497453 | controller | changed 2025-12-24 00:30:26.521647 | 2025-12-24 00:30:26.521783 | TASK [Run ensure-virtualenv role] 2025-12-24 00:30:26.559607 | controller | ok 2025-12-24 00:30:26.591059 | 2025-12-24 00:30:26.591204 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-24 00:30:26.870808 | controller | /usr/bin/virtualenv 2025-12-24 00:30:27.186839 | controller | ok: Runtime: 0:00:00.004306 2025-12-24 00:30:27.195225 | 2025-12-24 00:30:27.195318 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-24 00:30:27.218943 | controller | skipping: Conditional result was False 2025-12-24 00:30:27.219194 | controller | ok: All items complete 2025-12-24 00:30:27.219221 | 2025-12-24 00:30:27.234398 | 2025-12-24 00:30:27.234705 | TASK [Find the full path of the Python interpreter] 2025-12-24 00:30:27.433013 | controller | /usr/bin/python3 2025-12-24 00:30:27.768195 | controller | ok 2025-12-24 00:30:27.784843 | 2025-12-24 00:30:27.785257 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-24 00:30:28.717845 | controller | created virtual environment CPython3.11.0.final.0-64 in 513ms 2025-12-24 00:30:28.746786 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-24 00:30:28.746809 | 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-12-24 00:30:28.746817 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-24 00:30:28.746831 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-24 00:30:28.858597 | controller | changed 2025-12-24 00:30:28.868874 | 2025-12-24 00:30:28.869017 | TASK [Set selinux package] 2025-12-24 00:30:28.903211 | controller | ok 2025-12-24 00:30:28.909133 | 2025-12-24 00:30:28.909258 | TASK [Set selinux package (Fedora)] 2025-12-24 00:30:28.950230 | controller | ok 2025-12-24 00:30:28.956385 | 2025-12-24 00:30:28.956466 | TASK [Install selinux into virtualenv] 2025-12-24 00:30:54.439936 | controller | Collecting selinux-please-lie-to-me 2025-12-24 00:31:06.741592 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-24 00:31:07.052724 | controller | Collecting setuptools<50.0.0 2025-12-24 00:31:07.057830 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-24 00:31:07.096785 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 23.1 MB/s eta 0:00:00 2025-12-24 00:31:07.178226 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-24 00:31:07.178447 | controller | Attempting uninstall: setuptools 2025-12-24 00:31:07.180973 | controller | Found existing installation: setuptools 62.6.0 2025-12-24 00:31:07.245022 | controller | Uninstalling setuptools-62.6.0: 2025-12-24 00:31:07.253087 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-24 00:31:07.598167 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-24 00:31:19.064599 | controller | 2025-12-24 00:31:19.145580 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-24 00:31:19.145623 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-24 00:31:19.529765 | controller | ok: Runtime: 0:00:49.971899 2025-12-24 00:31:19.537923 | 2025-12-24 00:31:19.538011 | TASK [Install pytest-forked into virtualenv] 2025-12-24 00:31:56.335770 | controller | Collecting pytest-forked 2025-12-24 00:32:08.590083 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-24 00:32:08.633155 | controller | Collecting py 2025-12-24 00:32:08.637392 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-24 00:32:08.659991 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.0 MB/s eta 0:00:00 2025-12-24 00:32:08.765503 | controller | Collecting pytest>=3.10 2025-12-24 00:32:08.770571 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-24 00:32:08.787770 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 26.2 MB/s eta 0:00:00 2025-12-24 00:32:08.825205 | controller | Collecting iniconfig>=1.0.1 2025-12-24 00:32:08.828682 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-24 00:32:08.870534 | controller | Collecting packaging>=22 2025-12-24 00:32:08.873671 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-24 00:32:08.879212 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 18.4 MB/s eta 0:00:00 2025-12-24 00:32:08.908595 | controller | Collecting pluggy<2,>=1.5 2025-12-24 00:32:08.913538 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-24 00:32:08.957856 | controller | Collecting pygments>=2.7.2 2025-12-24 00:32:08.963022 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-24 00:32:09.002169 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 34.4 MB/s eta 0:00:00 2025-12-24 00:32:09.071578 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-24 00:32:10.143882 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0 2025-12-24 00:32:10.152559 | controller | 2025-12-24 00:32:10.223554 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-24 00:32:10.223597 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-24 00:32:10.613449 | controller | ok: Runtime: 0:00:50.466399 2025-12-24 00:32:10.619971 | 2025-12-24 00:32:10.620078 | TASK [Update pip] 2025-12-24 00:32:11.157974 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-24 00:32:20.965637 | controller | Collecting pip 2025-12-24 00:32:33.158303 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-24 00:32:33.209722 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 38.4 MB/s eta 0:00:00 2025-12-24 00:32:33.277443 | controller | Installing collected packages: pip 2025-12-24 00:32:33.277598 | controller | Attempting uninstall: pip 2025-12-24 00:32:33.279877 | controller | Found existing installation: pip 22.2.2 2025-12-24 00:32:33.419852 | controller | Uninstalling pip-22.2.2: 2025-12-24 00:32:33.435345 | controller | Successfully uninstalled pip-22.2.2 2025-12-24 00:32:34.257748 | controller | Successfully installed pip-25.3 2025-12-24 00:32:34.679312 | controller | ok: Runtime: 0:00:23.476420 2025-12-24 00:32:34.691664 | 2025-12-24 00:32:34.691830 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-24 00:32:34.909295 | controller | changed 2025-12-24 00:32:34.914799 | 2025-12-24 00:32:34.914891 | TASK [Install ansible into virtualenv] 2025-12-24 00:32:35.421057 | controller | Processing ./src/github.com/ansible/ansible 2025-12-24 00:32:35.424510 | controller | Installing build dependencies: started 2025-12-24 00:33:08.023863 | controller | Installing build dependencies: finished with status 'done' 2025-12-24 00:33:08.024576 | controller | Getting requirements to build wheel: started 2025-12-24 00:33:08.771749 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-24 00:33:08.773013 | controller | Preparing metadata (pyproject.toml): started 2025-12-24 00:33:09.237752 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-24 00:33:09.243749 | 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-12-24 00:33:09.249397 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-24 00:33:09.468628 | controller | ERROR 2025-12-24 00:33:09.468873 | controller | { 2025-12-24 00:33:09.468920 | controller | "delta": "0:00:34.184971", 2025-12-24 00:33:09.468947 | controller | "end": "2025-12-24 00:33:09.320535", 2025-12-24 00:33:09.468971 | controller | "msg": "non-zero return code", 2025-12-24 00:33:09.469007 | controller | "rc": 1, 2025-12-24 00:33:09.469029 | controller | "start": "2025-12-24 00:32:35.135564" 2025-12-24 00:33:09.469050 | controller | } failure 2025-12-24 00:33:09.470859 | 2025-12-24 00:33:09.470925 | PLAY RECAP 2025-12-24 00:33:09.470977 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-24 00:33:09.471005 | 2025-12-24 00:33:09.579655 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-24 00:33:09.580846 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-24 00:33:10.199305 | 2025-12-24 00:33:10.199415 | PLAY [all] 2025-12-24 00:33:10.221017 | 2025-12-24 00:33:10.221135 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-24 00:33:10.493790 | controller | changed: non-zero return code 2025-12-24 00:33:10.506631 | 2025-12-24 00:33:10.506867 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-24 00:33:10.533317 | controller | skipping: Conditional result was False 2025-12-24 00:33:10.542631 | 2025-12-24 00:33:10.542775 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-24 00:33:10.576777 | 2025-12-24 00:33:10.576968 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-24 00:33:10.611384 | 2025-12-24 00:33:10.611590 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-24 00:33:10.636358 | controller | skipping: Conditional result was False 2025-12-24 00:33:10.646546 | 2025-12-24 00:33:10.646666 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-24 00:33:10.680231 | 2025-12-24 00:33:10.680438 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-24 00:33:10.696327 | controller | skipping: Conditional result was False 2025-12-24 00:33:10.706510 | 2025-12-24 00:33:10.706654 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-24 00:33:10.726842 | controller | skipping: Conditional result was False 2025-12-24 00:33:10.736931 | 2025-12-24 00:33:10.737075 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-24 00:33:10.757010 | controller | skipping: Conditional result was False 2025-12-24 00:33:10.794290 | 2025-12-24 00:33:10.794386 | PLAY RECAP 2025-12-24 00:33:10.794430 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-24 00:33:10.794450 | 2025-12-24 00:33:10.890467 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-24 00:33:10.891576 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-24 00:33:11.443567 | 2025-12-24 00:33:11.443708 | PLAY [all:!appliance*] 2025-12-24 00:33:11.467433 | 2025-12-24 00:33:11.467558 | TASK [unregister the node] 2025-12-24 00:33:12.000156 | controller | skipping: Conditional result was False 2025-12-24 00:33:12.005875 | 2025-12-24 00:33:12.005955 | TASK [include_role : fetch-output] 2025-12-24 00:33:12.053783 | controller | ok 2025-12-24 00:33:12.089988 | 2025-12-24 00:33:12.090128 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-24 00:33:12.156450 | controller | skipping: Conditional result was False 2025-12-24 00:33:12.165832 | 2025-12-24 00:33:12.166001 | TASK [fetch-output : Set log path for single node] 2025-12-24 00:33:12.212919 | controller | ok 2025-12-24 00:33:12.225401 | 2025-12-24 00:33:12.225577 | LOOP [fetch-output : Ensure local output dirs] 2025-12-24 00:33:12.628752 | controller -> localhost | ok: "/var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/work/logs" 2025-12-24 00:33:12.880491 | controller -> localhost | changed: "/var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/work/artifacts" 2025-12-24 00:33:13.135908 | controller -> localhost | changed: "/var/lib/zuul/builds/351888a9753b4c799f797a4835da9eb4/work/docs" 2025-12-24 00:33:13.148192 | 2025-12-24 00:33:13.148311 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-24 00:33:13.893659 | controller | changed: 2025-12-24 00:33:13.901365 | controller | .d..t...... ./ 2025-12-24 00:33:13.901433 | controller | cd+++++++++ controller/ 2025-12-24 00:33:13.901471 | controller | changed: All items complete 2025-12-24 00:33:13.901491 | 2025-12-24 00:33:14.433496 | controller | changed: .d..t...... ./ 2025-12-24 00:33:14.994361 | controller | changed: .d..t...... ./ 2025-12-24 00:33:15.018977 | 2025-12-24 00:33:15.019103 | TASK [include_role : fetch-output-openshift] 2025-12-24 00:33:15.043594 | controller | skipping: Conditional result was False 2025-12-24 00:33:15.051780 | 2025-12-24 00:33:15.051925 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-24 00:33:15.079104 | controller | skipping: Conditional result was False 2025-12-24 00:33:15.087998 | controller | skipping: Conditional result was False 2025-12-24 00:33:15.129890 | 2025-12-24 00:33:15.129996 | PLAY [localhost] 2025-12-24 00:33:15.145738 | 2025-12-24 00:33:15.145817 | TASK [Run Zuul manifest role] 2025-12-24 00:33:15.164540 | localhost | ok 2025-12-24 00:33:15.181867 | 2025-12-24 00:33:15.181959 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-24 00:33:15.568320 | localhost | changed 2025-12-24 00:33:15.573691 | 2025-12-24 00:33:15.573818 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-24 00:33:15.603840 | localhost | ok 2025-12-24 00:33:15.614846 | 2025-12-24 00:33:15.614944 | TASK [Set zuul-log-path fact] 2025-12-24 00:33:15.633821 | localhost | ok 2025-12-24 00:33:15.649121 | 2025-12-24 00:33:15.649270 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-24 00:33:15.679901 | localhost | ok 2025-12-24 00:33:15.689929 | 2025-12-24 00:33:15.690044 | LOOP [Run upload-logs-swift role] 2025-12-24 00:33:15.715905 | localhost | Output suppressed because no_log was given 2025-12-24 00:33:15.744868 | 2025-12-24 00:33:15.745002 | TASK [Set zuul-log-path fact] 2025-12-24 00:33:15.769608 | localhost | skipping: Conditional result was False 2025-12-24 00:33:15.775179 | 2025-12-24 00:33:15.775258 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-24 00:33:16.193775 | localhost -> localhost | ok: Runtime: 0:00:00.006055 2025-12-24 00:33:16.233499 | 2025-12-24 00:33:16.233633 | TASK [upload-logs-swift : Upload logs to swift]