2025-12-20 00:06:39.586457 | Job console starting... 2025-12-20 00:06:39.598657 | Updating repositories 2025-12-20 00:06:39.731082 | Preparing job workspace 2025-12-20 00:06:43.335070 | Running Ansible setup... 2025-12-20 00:06:47.823290 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-20 00:06:48.575057 | 2025-12-20 00:06:48.575206 | PLAY [localhost] 2025-12-20 00:06:48.584024 | 2025-12-20 00:06:48.584095 | TASK [Gathering Facts] 2025-12-20 00:06:49.578862 | localhost | ok 2025-12-20 00:06:49.601835 | 2025-12-20 00:06:49.602003 | TASK [Setup log path fact] 2025-12-20 00:06:49.624037 | localhost | ok 2025-12-20 00:06:49.662833 | 2025-12-20 00:06:49.662954 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-20 00:06:49.701786 | localhost | ok 2025-12-20 00:06:49.710559 | 2025-12-20 00:06:49.710666 | TASK [emit-job-header : Print job information] 2025-12-20 00:06:49.760106 | # Job Information 2025-12-20 00:06:49.760271 | Ansible Version: 2.15.12 2025-12-20 00:06:49.760303 | Job: ansible-test-sanity-docker-milestone 2025-12-20 00:06:49.760325 | Pipeline: periodic 2025-12-20 00:06:49.760344 | Executor: ze03.softwarefactory-project.io 2025-12-20 00:06:49.760363 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-20 00:06:49.760385 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/f57/ansible/f57a9aad9e364c779498c9ee172d9ae9/ 2025-12-20 00:06:49.760405 | Event ID: e90b2a34aa9b47e1bd166d0e5d504958 2025-12-20 00:06:49.764348 | 2025-12-20 00:06:49.764423 | LOOP [emit-job-header : Print node information] 2025-12-20 00:06:49.890457 | localhost | ok: 2025-12-20 00:06:49.890905 | localhost | # Node Information 2025-12-20 00:06:49.890969 | localhost | Inventory Hostname: controller 2025-12-20 00:06:49.891014 | localhost | Hostname: np0005567542 2025-12-20 00:06:49.891057 | localhost | Username: zuul 2025-12-20 00:06:49.891103 | localhost | Distro: Fedora 37 2025-12-20 00:06:49.891143 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-20 00:06:49.891182 | localhost | Region: ca-ymq-1 2025-12-20 00:06:49.891219 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-20 00:06:49.891256 | localhost | Product Name: OpenStack Nova 2025-12-20 00:06:49.891293 | localhost | Interface IP: 162.253.55.74 2025-12-20 00:06:49.901534 | 2025-12-20 00:06:49.901667 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-20 00:06:50.359150 | localhost -> localhost | changed 2025-12-20 00:06:50.368859 | 2025-12-20 00:06:50.369044 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-20 00:06:51.238998 | localhost -> localhost | changed 2025-12-20 00:06:51.265590 | 2025-12-20 00:06:51.265774 | PLAY [all:!appliance*] 2025-12-20 00:06:51.297990 | 2025-12-20 00:06:51.298189 | TASK [include_role : start-zuul-console] 2025-12-20 00:06:51.324896 | controller | ok 2025-12-20 00:06:51.339931 | 2025-12-20 00:06:51.340050 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-20 00:06:51.723802 | controller | ok 2025-12-20 00:06:51.749345 | 2025-12-20 00:06:51.749495 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-20 00:06:52.574654 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-20 00:06:52.581050 | 2025-12-20 00:06:52.581123 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-20 00:06:53.124681 | controller | skipping: Conditional result was False 2025-12-20 00:06:53.131798 | 2025-12-20 00:06:53.131875 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-20 00:06:53.156806 | controller | skipping: Conditional result was False 2025-12-20 00:06:53.163530 | 2025-12-20 00:06:53.163603 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-20 00:06:53.187581 | controller | skipping: Conditional result was False 2025-12-20 00:06:53.193966 | 2025-12-20 00:06:53.194042 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-20 00:06:53.213588 | controller | skipping: Conditional result was False 2025-12-20 00:06:53.228131 | 2025-12-20 00:06:53.228300 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-20 00:06:53.254958 | controller | skipping: Conditional result was False 2025-12-20 00:06:53.263974 | 2025-12-20 00:06:53.264086 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-20 00:06:53.289910 | controller | skipping: Conditional result was False 2025-12-20 00:06:53.311074 | 2025-12-20 00:06:53.311233 | TASK [Disable Fedora Modular] 2025-12-20 00:06:53.560196 | controller | changed 2025-12-20 00:06:53.569383 | 2025-12-20 00:06:53.569515 | TASK [Enable EPEL] 2025-12-20 00:06:53.596990 | controller | skipping: Conditional result was False 2025-12-20 00:06:53.611867 | 2025-12-20 00:06:53.612006 | TASK [Register the RHEL node] 2025-12-20 00:06:54.168691 | 2025-12-20 00:06:54.169019 | TASK [Show the subscription-manager status] 2025-12-20 00:06:54.746233 | controller | skipping: Conditional result was False 2025-12-20 00:06:54.756982 | 2025-12-20 00:06:54.757086 | TASK [Enable EPEL on RHEL] 2025-12-20 00:06:55.311708 | controller | skipping: Conditional result was False 2025-12-20 00:06:55.318717 | 2025-12-20 00:06:55.318818 | TASK [Install git and tox] 2025-12-20 00:08:40.611505 | controller | changed 2025-12-20 00:08:40.623285 | 2025-12-20 00:08:40.624123 | TASK [include_role : prepare-workspace] 2025-12-20 00:08:40.683129 | controller | ok 2025-12-20 00:08:40.745104 | 2025-12-20 00:08:40.745303 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-20 00:08:41.022762 | controller | ok 2025-12-20 00:08:41.046391 | 2025-12-20 00:08:41.046582 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-20 00:08:55.498188 | controller | Output suppressed because no_log was given 2025-12-20 00:08:55.513615 | 2025-12-20 00:08:55.513882 | TASK [include_role : prepare-workspace-openshift] 2025-12-20 00:08:55.540537 | controller | skipping: Conditional result was False 2025-12-20 00:08:55.588299 | 2025-12-20 00:08:55.588424 | PLAY [all:!appliance] 2025-12-20 00:08:55.608616 | 2025-12-20 00:08:55.608741 | TASK [Run add-build-sshkey role (RSA)] 2025-12-20 00:08:55.640232 | controller | ok 2025-12-20 00:08:55.663335 | 2025-12-20 00:08:55.663436 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-20 00:08:55.935357 | controller -> localhost | ok 2025-12-20 00:08:55.942968 | 2025-12-20 00:08:55.943042 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-20 00:08:55.974943 | controller | ok 2025-12-20 00:08:56.008862 | controller | included: /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-20 00:08:56.016799 | 2025-12-20 00:08:56.016942 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-20 00:08:56.540460 | controller -> localhost | Generating public/private rsa key pair. 2025-12-20 00:08:56.540766 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/work/f57a9aad9e364c779498c9ee172d9ae9_id_rsa. 2025-12-20 00:08:56.540800 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/work/f57a9aad9e364c779498c9ee172d9ae9_id_rsa.pub. 2025-12-20 00:08:56.540822 | controller -> localhost | The key fingerprint is: 2025-12-20 00:08:56.540842 | controller -> localhost | SHA256:5ECj5cnGCqA+0C9027a9RqLosFgt0atiW1ryWPXujMQ zuul-build-sshkey 2025-12-20 00:08:56.540863 | controller -> localhost | The key's randomart image is: 2025-12-20 00:08:56.540882 | controller -> localhost | +---[RSA 2048]----+ 2025-12-20 00:08:56.540900 | controller -> localhost | |. + | 2025-12-20 00:08:56.540936 | controller -> localhost | |.o B o | 2025-12-20 00:08:56.540956 | controller -> localhost | |o + o B . | 2025-12-20 00:08:56.540974 | controller -> localhost | |o. = = + | 2025-12-20 00:08:56.540992 | controller -> localhost | | oo =.o S | 2025-12-20 00:08:56.541031 | controller -> localhost | | .+oooo. | 2025-12-20 00:08:56.541065 | controller -> localhost | |..o=oE.+. | 2025-12-20 00:08:56.541085 | controller -> localhost | |o=Xoo + .. | 2025-12-20 00:08:56.541104 | controller -> localhost | |+*+. ..=. | 2025-12-20 00:08:56.541125 | controller -> localhost | +----[SHA256]-----+ 2025-12-20 00:08:56.541187 | controller -> localhost | ok: Runtime: 0:00:00.066465 2025-12-20 00:08:56.559201 | 2025-12-20 00:08:56.559396 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-20 00:08:56.593114 | controller | ok 2025-12-20 00:08:56.606928 | controller | included: /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-20 00:08:56.623345 | 2025-12-20 00:08:56.623631 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-20 00:08:56.650931 | controller | skipping: Conditional result was False 2025-12-20 00:08:56.660980 | 2025-12-20 00:08:56.661190 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-20 00:08:57.200066 | controller | changed 2025-12-20 00:08:57.210141 | 2025-12-20 00:08:57.210314 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-20 00:08:57.445267 | controller | ok 2025-12-20 00:08:57.452035 | 2025-12-20 00:08:57.452108 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-20 00:08:58.114233 | controller | changed 2025-12-20 00:08:58.124547 | 2025-12-20 00:08:58.124742 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-20 00:08:58.811119 | controller | changed 2025-12-20 00:08:58.819669 | 2025-12-20 00:08:58.819835 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-20 00:08:58.846443 | controller | skipping: Conditional result was False 2025-12-20 00:08:58.866459 | 2025-12-20 00:08:58.866625 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-20 00:08:59.469545 | controller -> localhost | changed 2025-12-20 00:08:59.483648 | 2025-12-20 00:08:59.483796 | TASK [add-build-sshkey : Add back temp key] 2025-12-20 00:08:59.815657 | controller -> localhost | Identity added: /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/work/f57a9aad9e364c779498c9ee172d9ae9_id_rsa (zuul-build-sshkey) 2025-12-20 00:08:59.815902 | controller -> localhost | ok: Runtime: 0:00:00.008278 2025-12-20 00:08:59.822964 | 2025-12-20 00:08:59.823039 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-20 00:09:00.308281 | controller | ok 2025-12-20 00:09:00.327093 | 2025-12-20 00:09:00.327275 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-20 00:09:00.363689 | controller | skipping: Conditional result was False 2025-12-20 00:09:00.387832 | 2025-12-20 00:09:00.388049 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-20 00:09:00.436988 | controller | ok 2025-12-20 00:09:00.468996 | 2025-12-20 00:09:00.469224 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-20 00:09:00.826659 | controller -> localhost | ok 2025-12-20 00:09:00.838489 | 2025-12-20 00:09:00.838645 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-20 00:09:00.873988 | controller | ok 2025-12-20 00:09:00.889960 | controller | included: /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-20 00:09:00.899679 | 2025-12-20 00:09:00.899888 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-20 00:09:01.242225 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-20 00:09:01.242487 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/work/f57a9aad9e364c779498c9ee172d9ae9_id_ecdsa. 2025-12-20 00:09:01.242517 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/work/f57a9aad9e364c779498c9ee172d9ae9_id_ecdsa.pub. 2025-12-20 00:09:01.242547 | controller -> localhost | The key fingerprint is: 2025-12-20 00:09:01.242568 | controller -> localhost | SHA256:3pBzcQ3G4d/9GszL5S910+h2V6ELebCv6azWuR3rAQY zuul-build-sshkey 2025-12-20 00:09:01.242587 | controller -> localhost | The key's randomart image is: 2025-12-20 00:09:01.242606 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-20 00:09:01.242625 | controller -> localhost | | .+. | 2025-12-20 00:09:01.242643 | controller -> localhost | | o.o | 2025-12-20 00:09:01.242697 | controller -> localhost | | E. o . | 2025-12-20 00:09:01.242720 | controller -> localhost | | ..+ . o.| 2025-12-20 00:09:01.242758 | controller -> localhost | | S .o+ o.=| 2025-12-20 00:09:01.242778 | controller -> localhost | | . =.+.=..*| 2025-12-20 00:09:01.242796 | controller -> localhost | | . o =+=.*| 2025-12-20 00:09:01.242821 | controller -> localhost | | ..oo+B*o| 2025-12-20 00:09:01.242846 | controller -> localhost | | ..o*+=+o=| 2025-12-20 00:09:01.242864 | controller -> localhost | +----[SHA256]-----+ 2025-12-20 00:09:01.242922 | controller -> localhost | ok: Runtime: 0:00:00.014019 2025-12-20 00:09:01.257518 | 2025-12-20 00:09:01.257682 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-20 00:09:01.297763 | controller | ok 2025-12-20 00:09:01.319851 | controller | included: /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-20 00:09:01.329580 | 2025-12-20 00:09:01.329654 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-20 00:09:01.364239 | controller | skipping: Conditional result was False 2025-12-20 00:09:01.371384 | 2025-12-20 00:09:01.371455 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-20 00:09:01.686300 | controller | changed 2025-12-20 00:09:01.693150 | 2025-12-20 00:09:01.693217 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-20 00:09:01.928181 | controller | ok 2025-12-20 00:09:01.934088 | 2025-12-20 00:09:01.934161 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-20 00:09:02.615973 | controller | changed 2025-12-20 00:09:02.629395 | 2025-12-20 00:09:02.629553 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-20 00:09:03.356205 | controller | changed 2025-12-20 00:09:03.369626 | 2025-12-20 00:09:03.369793 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-20 00:09:03.396407 | controller | skipping: Conditional result was False 2025-12-20 00:09:03.403913 | 2025-12-20 00:09:03.403999 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-20 00:09:03.678487 | controller -> localhost | changed 2025-12-20 00:09:03.692179 | 2025-12-20 00:09:03.692292 | TASK [add-build-sshkey : Add back temp key] 2025-12-20 00:09:04.005073 | controller -> localhost | Identity added: /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/work/f57a9aad9e364c779498c9ee172d9ae9_id_ecdsa (zuul-build-sshkey) 2025-12-20 00:09:04.005297 | controller -> localhost | ok: Runtime: 0:00:00.008943 2025-12-20 00:09:04.012355 | 2025-12-20 00:09:04.012426 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-20 00:09:04.234095 | controller | ok 2025-12-20 00:09:04.244400 | 2025-12-20 00:09:04.244568 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-20 00:09:04.270712 | controller | skipping: Conditional result was False 2025-12-20 00:09:04.284151 | 2025-12-20 00:09:04.284284 | TASK [include_role : remove-zuul-sshkey] 2025-12-20 00:09:04.299601 | controller | skipping: Conditional result was False 2025-12-20 00:09:04.308908 | 2025-12-20 00:09:04.309012 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-20 00:09:04.542614 | controller | ok: "logs" 2025-12-20 00:09:04.543128 | controller | ok: All items complete 2025-12-20 00:09:04.543191 | 2025-12-20 00:09:04.740016 | controller | ok: "artifacts" 2025-12-20 00:09:04.921495 | controller | ok: "docs" 2025-12-20 00:09:04.930300 | 2025-12-20 00:09:04.930377 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-20 00:09:05.158652 | controller | changed: "logs" 2025-12-20 00:09:05.355562 | controller | changed: "artifacts" 2025-12-20 00:09:05.557298 | controller | changed: "docs" 2025-12-20 00:09:05.592748 | 2025-12-20 00:09:05.592871 | PLAY RECAP 2025-12-20 00:09:05.592918 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-20 00:09:05.592945 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-20 00:09:05.592963 | 2025-12-20 00:09:05.733196 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-20 00:09:05.734159 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-20 00:09:06.409562 | 2025-12-20 00:09:06.409717 | PLAY [all] 2025-12-20 00:09:06.437509 | 2025-12-20 00:09:06.437713 | TASK [Install binary dependencies] 2025-12-20 00:09:06.490647 | controller | ok 2025-12-20 00:09:06.513365 | 2025-12-20 00:09:06.513505 | TASK [bindep : Include find tasks] 2025-12-20 00:09:06.546516 | controller | ok 2025-12-20 00:09:06.554771 | controller | included: /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-20 00:09:06.561523 | 2025-12-20 00:09:06.561655 | TASK [bindep : Look for bindep.txt] 2025-12-20 00:09:06.970886 | controller | ok 2025-12-20 00:09:06.987402 | 2025-12-20 00:09:06.987569 | TASK [bindep : Define bindep_file fact] 2025-12-20 00:09:07.013582 | controller | skipping: Conditional result was False 2025-12-20 00:09:07.023699 | 2025-12-20 00:09:07.023915 | TASK [bindep : Look for other-requirements.txt] 2025-12-20 00:09:07.252836 | controller | ok 2025-12-20 00:09:07.262103 | 2025-12-20 00:09:07.262208 | TASK [bindep : Define bindep_file fact] 2025-12-20 00:09:07.287470 | controller | skipping: Conditional result was False 2025-12-20 00:09:07.299040 | 2025-12-20 00:09:07.299181 | TASK [bindep : Look for bindep fallback file] 2025-12-20 00:09:07.325162 | controller | skipping: Conditional result was False 2025-12-20 00:09:07.336626 | 2025-12-20 00:09:07.336835 | TASK [bindep : Define bindep_file fact] 2025-12-20 00:09:07.364414 | controller | skipping: Conditional result was False 2025-12-20 00:09:07.371324 | 2025-12-20 00:09:07.371415 | TASK [bindep : Include bindep tasks] 2025-12-20 00:09:07.395379 | controller | skipping: Conditional result was False 2025-12-20 00:09:07.402179 | 2025-12-20 00:09:07.402261 | TASK [bindep : Include install tasks] 2025-12-20 00:09:07.436988 | controller | skipping: Conditional result was False 2025-12-20 00:09:07.444344 | 2025-12-20 00:09:07.444472 | LOOP [bindep : Include package tasks] 2025-12-20 00:09:07.515105 | 2025-12-20 00:09:07.515378 | TASK [Run test-setup role] 2025-12-20 00:09:07.538085 | controller | ok 2025-12-20 00:09:07.555847 | 2025-12-20 00:09:07.555953 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-20 00:09:07.769986 | controller | ok 2025-12-20 00:09:07.776807 | 2025-12-20 00:09:07.776878 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-20 00:09:08.313043 | controller | skipping: Conditional result was False 2025-12-20 00:09:08.347221 | 2025-12-20 00:09:08.347343 | PLAY RECAP 2025-12-20 00:09:08.347401 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-20 00:09:08.347430 | 2025-12-20 00:09:08.476606 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-20 00:09:08.477559 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-20 00:09:09.159816 | 2025-12-20 00:09:09.160000 | PLAY [controller] 2025-12-20 00:09:09.181113 | 2025-12-20 00:09:09.181226 | TASK [Create the /root directory] 2025-12-20 00:09:09.594584 | controller | ok 2025-12-20 00:09:09.609904 | 2025-12-20 00:09:09.610157 | TASK [Install glibc-langpack-en] 2025-12-20 00:09:14.718028 | controller | ok: Nothing to do 2025-12-20 00:09:14.728359 | 2025-12-20 00:09:14.728546 | TASK [Ensure controller directory exists] 2025-12-20 00:09:14.953455 | controller | changed 2025-12-20 00:09:14.959956 | 2025-12-20 00:09:14.960035 | TASK [Install container runtime] 2025-12-20 00:09:15.024898 | controller | ok 2025-12-20 00:09:15.065364 | 2025-12-20 00:09:15.065510 | LOOP [ensure-podman : Find distribution installation] 2025-12-20 00:09:15.095231 | controller | ok: "/var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-20 00:09:15.103016 | controller | included: /var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-20 00:09:15.110216 | 2025-12-20 00:09:15.110281 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-20 00:10:28.722557 | controller | changed 2025-12-20 00:10:28.730542 | 2025-12-20 00:10:28.730636 | TASK [ensure-podman : Fetch podman version] 2025-12-20 00:10:29.449173 | controller | Client: Podman Engine 2025-12-20 00:10:29.478807 | controller | Version: 4.6.2 2025-12-20 00:10:29.478844 | controller | API Version: 4.6.2 2025-12-20 00:10:29.478852 | controller | Go Version: go1.19.12 2025-12-20 00:10:29.478872 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-20 00:10:29.478880 | controller | OS/Arch: linux/amd64 2025-12-20 00:10:29.770943 | controller | ok: Runtime: 0:00:00.356185 2025-12-20 00:10:29.779340 | 2025-12-20 00:10:29.779513 | TASK [ensure-podman : Print podman version installed] 2025-12-20 00:10:29.813954 | Podman version: Client: Podman Engine 2025-12-20 00:10:29.814137 | Version: 4.6.2 2025-12-20 00:10:29.814166 | API Version: 4.6.2 2025-12-20 00:10:29.814186 | Go Version: go1.19.12 2025-12-20 00:10:29.814203 | Built: Mon Aug 28 19:38:31 2023 2025-12-20 00:10:29.814221 | OS/Arch: linux/amd64 2025-12-20 00:10:29.820953 | 2025-12-20 00:10:29.821061 | TASK [ensure-podman : Validate podman engine] 2025-12-20 00:10:30.351505 | controller | skipping: Conditional result was False 2025-12-20 00:10:30.359031 | 2025-12-20 00:10:30.359118 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-20 00:10:30.374991 | controller | skipping: Conditional result was False 2025-12-20 00:10:30.388557 | 2025-12-20 00:10:30.388679 | TASK [Ensure python3.8 is present] 2025-12-20 00:10:30.418098 | controller | skipping: Conditional result was False 2025-12-20 00:10:30.425515 | 2025-12-20 00:10:30.425593 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-20 00:10:30.446061 | controller | ok 2025-12-20 00:10:30.468182 | 2025-12-20 00:10:30.468321 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-20 00:10:31.835172 | controller | ok: Nothing to do 2025-12-20 00:10:31.841121 | 2025-12-20 00:10:31.841196 | TASK [our-ensure-python : Also install python3-devel] 2025-12-20 00:10:44.179562 | controller | changed 2025-12-20 00:10:44.214705 | 2025-12-20 00:10:44.214871 | TASK [Run ensure-virtualenv role] 2025-12-20 00:10:44.262160 | controller | ok 2025-12-20 00:10:44.325750 | 2025-12-20 00:10:44.325890 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-20 00:10:44.808121 | controller | /usr/bin/virtualenv 2025-12-20 00:10:45.093329 | controller | ok: Runtime: 0:00:00.004997 2025-12-20 00:10:45.099904 | 2025-12-20 00:10:45.099993 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-20 00:10:45.140466 | controller | skipping: Conditional result was False 2025-12-20 00:10:45.140835 | controller | ok: All items complete 2025-12-20 00:10:45.140876 | 2025-12-20 00:10:45.167330 | 2025-12-20 00:10:45.167523 | TASK [Find the full path of the Python interpreter] 2025-12-20 00:10:45.449642 | controller | /usr/bin/python3 2025-12-20 00:10:45.741915 | controller | ok 2025-12-20 00:10:45.750315 | 2025-12-20 00:10:45.750399 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-20 00:10:46.578616 | controller | created virtual environment CPython3.11.0.final.0-64 in 473ms 2025-12-20 00:10:46.595426 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-20 00:10:46.595467 | 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-20 00:10:46.595477 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-20 00:10:46.595492 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-20 00:10:46.833719 | controller | changed 2025-12-20 00:10:46.841959 | 2025-12-20 00:10:46.842118 | TASK [Set selinux package] 2025-12-20 00:10:46.890937 | controller | ok 2025-12-20 00:10:46.900116 | 2025-12-20 00:10:46.900287 | TASK [Set selinux package (Fedora)] 2025-12-20 00:10:46.993370 | controller | ok 2025-12-20 00:10:47.006361 | 2025-12-20 00:10:47.006873 | TASK [Install selinux into virtualenv] 2025-12-20 00:11:12.557056 | controller | Collecting selinux-please-lie-to-me 2025-12-20 00:11:48.751425 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-20 00:11:49.068227 | controller | Collecting setuptools<50.0.0 2025-12-20 00:11:49.075995 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-20 00:11:49.109621 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 26.5 MB/s eta 0:00:00 2025-12-20 00:11:49.194517 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-20 00:11:49.194758 | controller | Attempting uninstall: setuptools 2025-12-20 00:11:49.197129 | controller | Found existing installation: setuptools 62.6.0 2025-12-20 00:11:49.256704 | controller | Uninstalling setuptools-62.6.0: 2025-12-20 00:11:49.264709 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-20 00:11:49.604804 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-20 00:12:06.929364 | controller | 2025-12-20 00:12:07.021944 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-20 00:12:07.021990 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-20 00:12:07.109632 | controller | ok: Runtime: 0:01:19.754616 2025-12-20 00:12:07.121976 | 2025-12-20 00:12:07.122152 | TASK [Install pytest-forked into virtualenv] 2025-12-20 00:12:20.029516 | controller | Collecting pytest-forked 2025-12-20 00:12:32.271134 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-20 00:12:32.314292 | controller | Collecting py 2025-12-20 00:12:32.319349 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-20 00:12:32.340670 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.0 MB/s eta 0:00:00 2025-12-20 00:12:32.447968 | controller | Collecting pytest>=3.10 2025-12-20 00:12:32.451533 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-20 00:12:32.465192 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 37.7 MB/s eta 0:00:00 2025-12-20 00:12:32.503264 | controller | Collecting iniconfig>=1.0.1 2025-12-20 00:12:32.506668 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-20 00:12:32.547990 | controller | Collecting packaging>=22 2025-12-20 00:12:32.551189 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-20 00:12:32.558836 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.9 MB/s eta 0:00:00 2025-12-20 00:12:32.589697 | controller | Collecting pluggy<2,>=1.5 2025-12-20 00:12:32.593291 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-20 00:12:32.645376 | controller | Collecting pygments>=2.7.2 2025-12-20 00:12:32.712672 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-20 00:12:32.739788 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 55.2 MB/s eta 0:00:00 2025-12-20 00:12:32.808900 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-20 00:12:33.823356 | 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-20 00:12:33.832191 | controller | 2025-12-20 00:12:33.897561 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-20 00:12:33.897626 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-20 00:12:34.189296 | controller | ok: Runtime: 0:00:26.533473 2025-12-20 00:12:34.196944 | 2025-12-20 00:12:34.197062 | TASK [Update pip] 2025-12-20 00:12:34.740978 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-20 00:12:44.668479 | controller | Collecting pip 2025-12-20 00:12:56.849446 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-20 00:12:56.909045 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 33.2 MB/s eta 0:00:00 2025-12-20 00:12:56.972651 | controller | Installing collected packages: pip 2025-12-20 00:12:56.972788 | controller | Attempting uninstall: pip 2025-12-20 00:12:56.974951 | controller | Found existing installation: pip 22.2.2 2025-12-20 00:12:57.116141 | controller | Uninstalling pip-22.2.2: 2025-12-20 00:12:57.131030 | controller | Successfully uninstalled pip-22.2.2 2025-12-20 00:12:57.935691 | controller | Successfully installed pip-25.3 2025-12-20 00:12:58.286572 | controller | ok: Runtime: 0:00:23.572438 2025-12-20 00:12:58.295977 | 2025-12-20 00:12:58.296119 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-20 00:12:58.537644 | controller | changed 2025-12-20 00:12:58.549654 | 2025-12-20 00:12:58.549817 | TASK [Install ansible into virtualenv] 2025-12-20 00:12:59.211556 | controller | Processing ./src/github.com/ansible/ansible 2025-12-20 00:12:59.214996 | controller | Installing build dependencies: started 2025-12-20 00:13:30.654807 | controller | Installing build dependencies: finished with status 'done' 2025-12-20 00:13:30.655483 | controller | Getting requirements to build wheel: started 2025-12-20 00:13:31.366896 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-20 00:13:31.368504 | controller | Preparing metadata (pyproject.toml): started 2025-12-20 00:13:31.823486 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-20 00:13:31.828521 | 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-20 00:13:31.832293 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-20 00:13:32.126800 | controller | ERROR 2025-12-20 00:13:32.127044 | controller | { 2025-12-20 00:13:32.127076 | controller | "delta": "0:00:33.041179", 2025-12-20 00:13:32.127096 | controller | "end": "2025-12-20 00:13:31.897460", 2025-12-20 00:13:32.127114 | controller | "msg": "non-zero return code", 2025-12-20 00:13:32.127147 | controller | "rc": 1, 2025-12-20 00:13:32.127164 | controller | "start": "2025-12-20 00:12:58.856281" 2025-12-20 00:13:32.127179 | controller | } failure 2025-12-20 00:13:32.129640 | 2025-12-20 00:13:32.129835 | PLAY RECAP 2025-12-20 00:13:32.129902 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-20 00:13:32.129928 | 2025-12-20 00:13:32.299595 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-20 00:13:32.300670 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-20 00:13:32.927368 | 2025-12-20 00:13:32.927500 | PLAY [all] 2025-12-20 00:13:32.952270 | 2025-12-20 00:13:32.952447 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-20 00:13:33.206448 | controller | changed: non-zero return code 2025-12-20 00:13:33.219661 | 2025-12-20 00:13:33.219902 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-20 00:13:33.237144 | controller | skipping: Conditional result was False 2025-12-20 00:13:33.250553 | 2025-12-20 00:13:33.250762 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-20 00:13:33.274835 | 2025-12-20 00:13:33.274973 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-20 00:13:33.306530 | 2025-12-20 00:13:33.307114 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-20 00:13:33.322318 | controller | skipping: Conditional result was False 2025-12-20 00:13:33.333277 | 2025-12-20 00:13:33.333393 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-20 00:13:33.358570 | 2025-12-20 00:13:33.358903 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-20 00:13:33.374398 | controller | skipping: Conditional result was False 2025-12-20 00:13:33.382264 | 2025-12-20 00:13:33.382371 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-20 00:13:33.396402 | controller | skipping: Conditional result was False 2025-12-20 00:13:33.406897 | 2025-12-20 00:13:33.407032 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-20 00:13:33.433635 | controller | skipping: Conditional result was False 2025-12-20 00:13:33.474581 | 2025-12-20 00:13:33.474720 | PLAY RECAP 2025-12-20 00:13:33.474803 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-20 00:13:33.474841 | 2025-12-20 00:13:33.622184 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-20 00:13:33.624627 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-20 00:13:34.308541 | 2025-12-20 00:13:34.308779 | PLAY [all:!appliance*] 2025-12-20 00:13:34.335623 | 2025-12-20 00:13:34.335856 | TASK [unregister the node] 2025-12-20 00:13:34.870531 | controller | skipping: Conditional result was False 2025-12-20 00:13:34.877287 | 2025-12-20 00:13:34.877405 | TASK [include_role : fetch-output] 2025-12-20 00:13:34.907719 | controller | ok 2025-12-20 00:13:34.929034 | 2025-12-20 00:13:34.929152 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-20 00:13:34.984864 | controller | skipping: Conditional result was False 2025-12-20 00:13:35.002397 | 2025-12-20 00:13:35.002661 | TASK [fetch-output : Set log path for single node] 2025-12-20 00:13:35.046803 | controller | ok 2025-12-20 00:13:35.052360 | 2025-12-20 00:13:35.052443 | LOOP [fetch-output : Ensure local output dirs] 2025-12-20 00:13:35.475433 | controller -> localhost | ok: "/var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/work/logs" 2025-12-20 00:13:35.728813 | controller -> localhost | changed: "/var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/work/artifacts" 2025-12-20 00:13:35.950524 | controller -> localhost | changed: "/var/lib/zuul/builds/f57a9aad9e364c779498c9ee172d9ae9/work/docs" 2025-12-20 00:13:35.963560 | 2025-12-20 00:13:35.963788 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-20 00:13:36.676716 | controller | changed: 2025-12-20 00:13:36.676994 | controller | .d..t...... ./ 2025-12-20 00:13:36.677024 | controller | cd+++++++++ controller/ 2025-12-20 00:13:36.677281 | controller | changed: All items complete 2025-12-20 00:13:36.677328 | 2025-12-20 00:13:37.170406 | controller | changed: .d..t...... ./ 2025-12-20 00:13:37.659339 | controller | changed: .d..t...... ./ 2025-12-20 00:13:37.689967 | 2025-12-20 00:13:37.690148 | TASK [include_role : fetch-output-openshift] 2025-12-20 00:13:37.706064 | controller | skipping: Conditional result was False 2025-12-20 00:13:37.720627 | 2025-12-20 00:13:37.720818 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-20 00:13:37.750075 | controller | skipping: Conditional result was False 2025-12-20 00:13:37.761441 | controller | skipping: Conditional result was False 2025-12-20 00:13:37.818099 | 2025-12-20 00:13:37.818256 | PLAY [localhost] 2025-12-20 00:13:37.834324 | 2025-12-20 00:13:37.834444 | TASK [Run Zuul manifest role] 2025-12-20 00:13:37.853566 | localhost | ok 2025-12-20 00:13:37.871956 | 2025-12-20 00:13:37.872103 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-20 00:13:38.280692 | localhost | changed 2025-12-20 00:13:38.287267 | 2025-12-20 00:13:38.287363 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-20 00:13:38.318825 | localhost | ok 2025-12-20 00:13:38.328122 | 2025-12-20 00:13:38.328238 | TASK [Set zuul-log-path fact] 2025-12-20 00:13:38.347613 | localhost | ok 2025-12-20 00:13:38.363196 | 2025-12-20 00:13:38.363442 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-20 00:13:38.393042 | localhost | ok 2025-12-20 00:13:38.402006 | 2025-12-20 00:13:38.402100 | LOOP [Run upload-logs-swift role] 2025-12-20 00:13:38.437432 | localhost | Output suppressed because no_log was given 2025-12-20 00:13:38.470973 | 2025-12-20 00:13:38.471107 | TASK [Set zuul-log-path fact] 2025-12-20 00:13:38.516812 | localhost | skipping: Conditional result was False 2025-12-20 00:13:38.524375 | 2025-12-20 00:13:38.524513 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-20 00:13:38.969893 | localhost -> localhost | ok: Runtime: 0:00:00.005883 2025-12-20 00:13:38.980170 | 2025-12-20 00:13:38.980355 | TASK [upload-logs-swift : Upload logs to swift]