2025-12-01 00:22:03.169347 | Job console starting... 2025-12-01 00:22:03.179967 | Updating repositories 2025-12-01 00:22:03.345884 | Preparing job workspace 2025-12-01 00:22:07.643343 | Running Ansible setup... 2025-12-01 00:22:16.639351 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-01 00:22:17.403426 | 2025-12-01 00:22:17.403608 | PLAY [localhost] 2025-12-01 00:22:17.412871 | 2025-12-01 00:22:17.412946 | TASK [Gathering Facts] 2025-12-01 00:22:18.469187 | localhost | ok 2025-12-01 00:22:18.496960 | 2025-12-01 00:22:18.497172 | TASK [Setup log path fact] 2025-12-01 00:22:18.520256 | localhost | ok 2025-12-01 00:22:18.540898 | 2025-12-01 00:22:18.541060 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-01 00:22:18.576134 | localhost | ok 2025-12-01 00:22:18.601454 | 2025-12-01 00:22:18.601714 | TASK [emit-job-header : Print job information] 2025-12-01 00:22:18.644234 | # Job Information 2025-12-01 00:22:18.644431 | Ansible Version: 2.15.12 2025-12-01 00:22:18.644463 | Job: ansible-test-sanity-docker-devel 2025-12-01 00:22:18.644484 | Pipeline: periodic 2025-12-01 00:22:18.644503 | Executor: ze04.softwarefactory-project.io 2025-12-01 00:22:18.644521 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-01 00:22:18.644541 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/a98/ansible/a984c2db4042451c9a248b05668d1788/ 2025-12-01 00:22:18.644560 | Event ID: 7f239586727e4cf3b26e006c8a5b9dc9 2025-12-01 00:22:18.648445 | 2025-12-01 00:22:18.648510 | LOOP [emit-job-header : Print node information] 2025-12-01 00:22:18.760988 | localhost | ok: 2025-12-01 00:22:18.761288 | localhost | # Node Information 2025-12-01 00:22:18.761327 | localhost | Inventory Hostname: controller 2025-12-01 00:22:18.761355 | localhost | Hostname: np0005540485 2025-12-01 00:22:18.761381 | localhost | Username: zuul 2025-12-01 00:22:18.761414 | localhost | Distro: Fedora 37 2025-12-01 00:22:18.761441 | localhost | Provider: ansible-vexxhost-ams1 2025-12-01 00:22:18.761465 | localhost | Region: ams1 2025-12-01 00:22:18.761488 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-01 00:22:18.761519 | localhost | Product Name: OpenStack Nova 2025-12-01 00:22:18.761555 | localhost | Interface IP: 38.129.16.152 2025-12-01 00:22:18.772158 | 2025-12-01 00:22:18.772312 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-01 00:22:19.297637 | localhost -> localhost | changed 2025-12-01 00:22:19.311078 | 2025-12-01 00:22:19.311288 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-01 00:22:20.244005 | localhost -> localhost | changed 2025-12-01 00:22:20.288345 | 2025-12-01 00:22:20.288514 | PLAY [all:!appliance*] 2025-12-01 00:22:20.322779 | 2025-12-01 00:22:20.323440 | TASK [include_role : start-zuul-console] 2025-12-01 00:22:20.349884 | controller | ok 2025-12-01 00:22:20.366598 | 2025-12-01 00:22:20.366787 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-01 00:22:21.479932 | controller | ok 2025-12-01 00:22:21.505118 | 2025-12-01 00:22:21.505255 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-01 00:22:23.841022 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-01 00:22:23.863777 | 2025-12-01 00:22:23.863976 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-01 00:22:24.233853 | controller | skipping: Conditional result was False 2025-12-01 00:22:24.249920 | 2025-12-01 00:22:24.250083 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-01 00:22:24.280041 | controller | skipping: Conditional result was False 2025-12-01 00:22:24.298989 | 2025-12-01 00:22:24.299199 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-01 00:22:24.331389 | controller | skipping: Conditional result was False 2025-12-01 00:22:24.352947 | 2025-12-01 00:22:24.353222 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-01 00:22:24.405228 | controller | skipping: Conditional result was False 2025-12-01 00:22:24.416232 | 2025-12-01 00:22:24.416367 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-01 00:22:24.443828 | controller | skipping: Conditional result was False 2025-12-01 00:22:24.453717 | 2025-12-01 00:22:24.453845 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-01 00:22:24.470148 | controller | skipping: Conditional result was False 2025-12-01 00:22:24.489973 | 2025-12-01 00:22:24.490131 | TASK [Disable Fedora Modular] 2025-12-01 00:22:25.727265 | controller | changed 2025-12-01 00:22:25.733519 | 2025-12-01 00:22:25.733588 | TASK [Enable EPEL] 2025-12-01 00:22:25.770286 | controller | skipping: Conditional result was False 2025-12-01 00:22:25.778953 | 2025-12-01 00:22:25.779053 | TASK [Register the RHEL node] 2025-12-01 00:22:26.207651 | 2025-12-01 00:22:26.207991 | TASK [Show the subscription-manager status] 2025-12-01 00:22:26.596423 | controller | skipping: Conditional result was False 2025-12-01 00:22:26.606652 | 2025-12-01 00:22:26.606790 | TASK [Enable EPEL on RHEL] 2025-12-01 00:22:26.972458 | controller | skipping: Conditional result was False 2025-12-01 00:22:26.988600 | 2025-12-01 00:22:26.988791 | TASK [Install git and tox] 2025-12-01 00:24:35.688662 | controller | changed 2025-12-01 00:24:35.704769 | 2025-12-01 00:24:35.704969 | TASK [include_role : prepare-workspace] 2025-12-01 00:24:35.736606 | controller | ok 2025-12-01 00:24:35.777238 | 2025-12-01 00:24:35.777404 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-01 00:24:36.611576 | controller | ok 2025-12-01 00:24:36.621289 | 2025-12-01 00:24:36.621441 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-01 00:24:52.374525 | controller | Output suppressed because no_log was given 2025-12-01 00:24:52.391958 | 2025-12-01 00:24:52.392172 | TASK [include_role : prepare-workspace-openshift] 2025-12-01 00:24:52.416959 | controller | skipping: Conditional result was False 2025-12-01 00:24:52.468952 | 2025-12-01 00:24:52.469086 | PLAY [all:!appliance] 2025-12-01 00:24:52.484388 | 2025-12-01 00:24:52.484450 | TASK [Run add-build-sshkey role (RSA)] 2025-12-01 00:24:52.514126 | controller | ok 2025-12-01 00:24:52.528400 | 2025-12-01 00:24:52.528468 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-01 00:24:52.786436 | controller -> localhost | ok 2025-12-01 00:24:52.793338 | 2025-12-01 00:24:52.793408 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-01 00:24:52.835083 | controller | ok 2025-12-01 00:24:52.849539 | controller | included: /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-01 00:24:52.855886 | 2025-12-01 00:24:52.855968 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-01 00:24:53.329209 | controller -> localhost | Generating public/private rsa key pair. 2025-12-01 00:24:53.329483 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/work/a984c2db4042451c9a248b05668d1788_id_rsa. 2025-12-01 00:24:53.329522 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/work/a984c2db4042451c9a248b05668d1788_id_rsa.pub. 2025-12-01 00:24:53.329548 | controller -> localhost | The key fingerprint is: 2025-12-01 00:24:53.329572 | controller -> localhost | SHA256:+d8AxT5w970P3K5zQbviKgu0MZzK6tC9D5/ETXygX4U zuul-build-sshkey 2025-12-01 00:24:53.329597 | controller -> localhost | The key's randomart image is: 2025-12-01 00:24:53.329622 | controller -> localhost | +---[RSA 2048]----+ 2025-12-01 00:24:53.329645 | controller -> localhost | | | 2025-12-01 00:24:53.329669 | controller -> localhost | | .. | 2025-12-01 00:24:53.329717 | controller -> localhost | | ..E+.. | 2025-12-01 00:24:53.329742 | controller -> localhost | | . +..=.. o.| 2025-12-01 00:24:53.329766 | controller -> localhost | | BSo.oo . +| 2025-12-01 00:24:53.329801 | controller -> localhost | | . o + B.o. o +.| 2025-12-01 00:24:53.329849 | controller -> localhost | | . . = = o. . o.+| 2025-12-01 00:24:53.329877 | controller -> localhost | | . . = o. . +.+o| 2025-12-01 00:24:53.329901 | controller -> localhost | | .o ..+ .o.+.++o| 2025-12-01 00:24:53.329928 | controller -> localhost | +----[SHA256]-----+ 2025-12-01 00:24:53.329989 | controller -> localhost | ok: Runtime: 0:00:00.118505 2025-12-01 00:24:53.345149 | 2025-12-01 00:24:53.345243 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-01 00:24:53.376846 | controller | ok 2025-12-01 00:24:53.390637 | controller | included: /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-01 00:24:53.400257 | 2025-12-01 00:24:53.400329 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-01 00:24:53.424416 | controller | skipping: Conditional result was False 2025-12-01 00:24:53.434477 | 2025-12-01 00:24:53.434604 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-01 00:24:54.512472 | controller | changed 2025-12-01 00:24:54.522373 | 2025-12-01 00:24:54.522498 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-01 00:24:55.164501 | controller | ok 2025-12-01 00:24:55.179553 | 2025-12-01 00:24:55.179813 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-01 00:24:58.221709 | controller | changed 2025-12-01 00:24:58.236030 | 2025-12-01 00:24:58.236188 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-01 00:25:01.239274 | controller | changed 2025-12-01 00:25:01.245663 | 2025-12-01 00:25:01.245760 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-01 00:25:01.281787 | controller | skipping: Conditional result was False 2025-12-01 00:25:01.293334 | 2025-12-01 00:25:01.293498 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-01 00:25:01.768656 | controller -> localhost | changed 2025-12-01 00:25:01.783373 | 2025-12-01 00:25:01.783571 | TASK [add-build-sshkey : Add back temp key] 2025-12-01 00:25:02.073193 | controller -> localhost | Identity added: /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/work/a984c2db4042451c9a248b05668d1788_id_rsa (zuul-build-sshkey) 2025-12-01 00:25:02.073479 | controller -> localhost | ok: Runtime: 0:00:00.013646 2025-12-01 00:25:02.080216 | 2025-12-01 00:25:02.080283 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-01 00:25:03.009382 | controller | ok 2025-12-01 00:25:03.021551 | 2025-12-01 00:25:03.021755 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-01 00:25:03.062490 | controller | skipping: Conditional result was False 2025-12-01 00:25:03.084523 | 2025-12-01 00:25:03.084662 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-01 00:25:03.116877 | controller | ok 2025-12-01 00:25:03.132880 | 2025-12-01 00:25:03.132954 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-01 00:25:03.412712 | controller -> localhost | ok 2025-12-01 00:25:03.421836 | 2025-12-01 00:25:03.421960 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-01 00:25:03.467784 | controller | ok 2025-12-01 00:25:03.484804 | controller | included: /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-01 00:25:03.494452 | 2025-12-01 00:25:03.494592 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-01 00:25:03.838492 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-01 00:25:03.838811 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/work/a984c2db4042451c9a248b05668d1788_id_ecdsa. 2025-12-01 00:25:03.838857 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/work/a984c2db4042451c9a248b05668d1788_id_ecdsa.pub. 2025-12-01 00:25:03.838900 | controller -> localhost | The key fingerprint is: 2025-12-01 00:25:03.838931 | controller -> localhost | SHA256:+Vw/gItCVxihgCy3FCJTrdcjpaxxf8gxjNA1WYMrWts zuul-build-sshkey 2025-12-01 00:25:03.838961 | controller -> localhost | The key's randomart image is: 2025-12-01 00:25:03.838979 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-01 00:25:03.838997 | controller -> localhost | |+oo=..o+=. | 2025-12-01 00:25:03.839025 | controller -> localhost | |oo* o.+o + | 2025-12-01 00:25:03.839058 | controller -> localhost | | + = *... . | 2025-12-01 00:25:03.839092 | controller -> localhost | | + X B o . | 2025-12-01 00:25:03.839120 | controller -> localhost | | B B.=S . o | 2025-12-01 00:25:03.839139 | controller -> localhost | | o ..E..+ o o | 2025-12-01 00:25:03.839157 | controller -> localhost | | ... + o | 2025-12-01 00:25:03.839174 | controller -> localhost | | . . | 2025-12-01 00:25:03.839191 | controller -> localhost | | | 2025-12-01 00:25:03.839209 | controller -> localhost | +----[SHA256]-----+ 2025-12-01 00:25:03.839262 | controller -> localhost | ok: Runtime: 0:00:00.015936 2025-12-01 00:25:03.848719 | 2025-12-01 00:25:03.848851 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-01 00:25:03.889546 | controller | ok 2025-12-01 00:25:03.900520 | controller | included: /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-01 00:25:03.914661 | 2025-12-01 00:25:03.914854 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-01 00:25:03.951358 | controller | skipping: Conditional result was False 2025-12-01 00:25:03.959545 | 2025-12-01 00:25:03.959694 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-01 00:25:04.887762 | controller | changed 2025-12-01 00:25:04.943573 | 2025-12-01 00:25:04.943760 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-01 00:25:05.601262 | controller | ok 2025-12-01 00:25:05.614270 | 2025-12-01 00:25:05.614429 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-01 00:25:08.674458 | controller | changed 2025-12-01 00:25:08.680222 | 2025-12-01 00:25:08.680287 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-01 00:25:11.719024 | controller | changed 2025-12-01 00:25:11.733011 | 2025-12-01 00:25:11.733197 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-01 00:25:11.751470 | controller | skipping: Conditional result was False 2025-12-01 00:25:11.758809 | 2025-12-01 00:25:11.758926 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-01 00:25:12.019088 | controller -> localhost | changed 2025-12-01 00:25:12.043484 | 2025-12-01 00:25:12.043652 | TASK [add-build-sshkey : Add back temp key] 2025-12-01 00:25:12.347905 | controller -> localhost | Identity added: /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/work/a984c2db4042451c9a248b05668d1788_id_ecdsa (zuul-build-sshkey) 2025-12-01 00:25:12.348324 | controller -> localhost | ok: Runtime: 0:00:00.012741 2025-12-01 00:25:12.367898 | 2025-12-01 00:25:12.368111 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-01 00:25:13.073695 | controller | ok 2025-12-01 00:25:13.080781 | 2025-12-01 00:25:13.080887 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-01 00:25:13.127260 | controller | skipping: Conditional result was False 2025-12-01 00:25:13.143152 | 2025-12-01 00:25:13.143262 | TASK [include_role : remove-zuul-sshkey] 2025-12-01 00:25:13.172618 | controller | skipping: Conditional result was False 2025-12-01 00:25:13.181772 | 2025-12-01 00:25:13.181881 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-01 00:25:13.852549 | controller | ok: "logs" 2025-12-01 00:25:13.852853 | controller | ok: All items complete 2025-12-01 00:25:13.852892 | 2025-12-01 00:25:14.474737 | controller | ok: "artifacts" 2025-12-01 00:25:15.102326 | controller | ok: "docs" 2025-12-01 00:25:15.116866 | 2025-12-01 00:25:15.117011 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-01 00:25:15.811019 | controller | changed: "logs" 2025-12-01 00:25:16.424615 | controller | changed: "artifacts" 2025-12-01 00:25:17.059604 | controller | changed: "docs" 2025-12-01 00:25:17.124933 | 2025-12-01 00:25:17.125092 | PLAY RECAP 2025-12-01 00:25:17.125157 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-01 00:25:17.125194 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-01 00:25:17.125219 | 2025-12-01 00:25:17.274674 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-01 00:25:17.275714 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-01 00:25:17.834223 | 2025-12-01 00:25:17.834342 | PLAY [all] 2025-12-01 00:25:17.856062 | 2025-12-01 00:25:17.856166 | TASK [Install binary dependencies] 2025-12-01 00:25:17.928561 | controller | ok 2025-12-01 00:25:17.955789 | 2025-12-01 00:25:17.955913 | TASK [bindep : Include find tasks] 2025-12-01 00:25:18.002941 | controller | ok 2025-12-01 00:25:18.014873 | controller | included: /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-01 00:25:18.023693 | 2025-12-01 00:25:18.023817 | TASK [bindep : Look for bindep.txt] 2025-12-01 00:25:18.960610 | controller | ok 2025-12-01 00:25:18.974263 | 2025-12-01 00:25:18.974419 | TASK [bindep : Define bindep_file fact] 2025-12-01 00:25:18.992841 | controller | skipping: Conditional result was False 2025-12-01 00:25:19.008059 | 2025-12-01 00:25:19.008215 | TASK [bindep : Look for other-requirements.txt] 2025-12-01 00:25:19.650739 | controller | ok 2025-12-01 00:25:19.665669 | 2025-12-01 00:25:19.665893 | TASK [bindep : Define bindep_file fact] 2025-12-01 00:25:19.705439 | controller | skipping: Conditional result was False 2025-12-01 00:25:19.720511 | 2025-12-01 00:25:19.720710 | TASK [bindep : Look for bindep fallback file] 2025-12-01 00:25:19.747872 | controller | skipping: Conditional result was False 2025-12-01 00:25:19.760509 | 2025-12-01 00:25:19.760652 | TASK [bindep : Define bindep_file fact] 2025-12-01 00:25:19.786428 | controller | skipping: Conditional result was False 2025-12-01 00:25:19.799088 | 2025-12-01 00:25:19.799236 | TASK [bindep : Include bindep tasks] 2025-12-01 00:25:19.825437 | controller | skipping: Conditional result was False 2025-12-01 00:25:19.835228 | 2025-12-01 00:25:19.835331 | TASK [bindep : Include install tasks] 2025-12-01 00:25:19.860192 | controller | skipping: Conditional result was False 2025-12-01 00:25:19.869569 | 2025-12-01 00:25:19.869670 | LOOP [bindep : Include package tasks] 2025-12-01 00:25:19.938327 | 2025-12-01 00:25:19.938521 | TASK [Run test-setup role] 2025-12-01 00:25:19.959397 | controller | ok 2025-12-01 00:25:19.977859 | 2025-12-01 00:25:19.977978 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-01 00:25:20.597263 | controller | ok 2025-12-01 00:25:20.611781 | 2025-12-01 00:25:20.611922 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-01 00:25:20.982751 | controller | skipping: Conditional result was False 2025-12-01 00:25:21.037822 | 2025-12-01 00:25:21.037928 | PLAY RECAP 2025-12-01 00:25:21.037992 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-01 00:25:21.038020 | 2025-12-01 00:25:21.161324 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-01 00:25:21.162341 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-01 00:25:21.765177 | 2025-12-01 00:25:21.765329 | PLAY [controller] 2025-12-01 00:25:21.787642 | 2025-12-01 00:25:21.787820 | TASK [Create the /root directory] 2025-12-01 00:25:22.877870 | controller | ok 2025-12-01 00:25:22.891436 | 2025-12-01 00:25:22.891604 | TASK [Install glibc-langpack-en] 2025-12-01 00:25:31.073120 | controller | ok: Nothing to do 2025-12-01 00:25:31.082882 | 2025-12-01 00:25:31.082970 | TASK [Ensure controller directory exists] 2025-12-01 00:25:31.897620 | controller | changed 2025-12-01 00:25:31.913494 | 2025-12-01 00:25:31.913708 | TASK [Install container runtime] 2025-12-01 00:25:31.966634 | controller | ok 2025-12-01 00:25:32.029341 | 2025-12-01 00:25:32.029483 | LOOP [ensure-podman : Find distribution installation] 2025-12-01 00:25:32.067545 | controller | ok: "/var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-01 00:25:32.087490 | controller | included: /var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-01 00:25:32.098216 | 2025-12-01 00:25:32.098334 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-01 00:27:27.919456 | controller | changed 2025-12-01 00:27:27.934556 | 2025-12-01 00:27:27.934762 | TASK [ensure-podman : Fetch podman version] 2025-12-01 00:27:29.059561 | controller | Client: Podman Engine 2025-12-01 00:27:29.093484 | controller | Version: 4.6.2 2025-12-01 00:27:29.093544 | controller | API Version: 4.6.2 2025-12-01 00:27:29.093552 | controller | Go Version: go1.19.12 2025-12-01 00:27:29.093572 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-01 00:27:29.093581 | controller | OS/Arch: linux/amd64 2025-12-01 00:27:29.311145 | controller | ok: Runtime: 0:00:00.240261 2025-12-01 00:27:29.326534 | 2025-12-01 00:27:29.326736 | TASK [ensure-podman : Print podman version installed] 2025-12-01 00:27:29.369435 | Podman version: Client: Podman Engine 2025-12-01 00:27:29.369724 | Version: 4.6.2 2025-12-01 00:27:29.369793 | API Version: 4.6.2 2025-12-01 00:27:29.369840 | Go Version: go1.19.12 2025-12-01 00:27:29.369882 | Built: Mon Aug 28 19:38:31 2023 2025-12-01 00:27:29.369925 | OS/Arch: linux/amd64 2025-12-01 00:27:29.382308 | 2025-12-01 00:27:29.382439 | TASK [ensure-podman : Validate podman engine] 2025-12-01 00:27:29.750883 | controller | skipping: Conditional result was False 2025-12-01 00:27:29.765638 | 2025-12-01 00:27:29.765993 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-01 00:27:29.794091 | controller | skipping: Conditional result was False 2025-12-01 00:27:29.821521 | 2025-12-01 00:27:29.821765 | TASK [Ensure python3.8 is present] 2025-12-01 00:27:29.849229 | controller | skipping: Conditional result was False 2025-12-01 00:27:29.863080 | 2025-12-01 00:27:29.863248 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-01 00:27:29.893379 | controller | ok 2025-12-01 00:27:29.926952 | 2025-12-01 00:27:29.927087 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-01 00:27:33.494393 | controller | ok: Nothing to do 2025-12-01 00:27:33.506985 | 2025-12-01 00:27:33.507112 | TASK [our-ensure-python : Also install python3-devel] 2025-12-01 00:27:47.901628 | controller | changed 2025-12-01 00:27:47.918348 | 2025-12-01 00:27:47.918440 | TASK [Run ensure-virtualenv role] 2025-12-01 00:27:47.937997 | controller | ok 2025-12-01 00:27:47.958999 | 2025-12-01 00:27:47.959103 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-01 00:27:48.711587 | controller | /usr/bin/virtualenv 2025-12-01 00:27:49.312977 | controller | ok: Runtime: 0:00:00.007508 2025-12-01 00:27:49.330004 | 2025-12-01 00:27:49.330200 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-01 00:27:49.358960 | controller | skipping: Conditional result was False 2025-12-01 00:27:49.359270 | controller | ok: All items complete 2025-12-01 00:27:49.359308 | 2025-12-01 00:27:49.380804 | 2025-12-01 00:27:49.380946 | TASK [Find the full path of the Python interpreter] 2025-12-01 00:27:50.210889 | controller | /usr/bin/python3 2025-12-01 00:27:50.776299 | controller | ok 2025-12-01 00:27:50.782244 | 2025-12-01 00:27:50.782316 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-01 00:27:52.514932 | controller | created virtual environment CPython3.11.0.final.0-64 in 841ms 2025-12-01 00:27:52.605832 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-01 00:27:52.605890 | 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-01 00:27:52.605906 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-01 00:27:52.605926 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-01 00:27:53.145421 | controller | changed 2025-12-01 00:27:53.157172 | 2025-12-01 00:27:53.157343 | TASK [Set selinux package] 2025-12-01 00:27:53.181949 | controller | ok 2025-12-01 00:27:53.189331 | 2025-12-01 00:27:53.189473 | TASK [Set selinux package (Fedora)] 2025-12-01 00:27:53.233304 | controller | ok 2025-12-01 00:27:53.241867 | 2025-12-01 00:27:53.241992 | TASK [Install selinux into virtualenv] 2025-12-01 00:27:56.179589 | controller | Collecting selinux-please-lie-to-me 2025-12-01 00:27:56.244540 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-01 00:27:56.770284 | controller | Collecting setuptools<50.0.0 2025-12-01 00:27:56.774815 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-01 00:27:56.826745 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 17.1 MB/s eta 0:00:00 2025-12-01 00:27:56.966122 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-01 00:27:56.966328 | controller | Attempting uninstall: setuptools 2025-12-01 00:27:56.970914 | controller | Found existing installation: setuptools 62.6.0 2025-12-01 00:27:57.086743 | controller | Uninstalling setuptools-62.6.0: 2025-12-01 00:27:57.101824 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-01 00:27:57.990014 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-01 00:27:58.196289 | controller | 2025-12-01 00:27:58.461957 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-01 00:27:58.462016 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-01 00:27:58.623541 | controller | ok: Runtime: 0:00:04.355393 2025-12-01 00:27:58.629439 | 2025-12-01 00:27:58.629509 | TASK [Install pytest-forked into virtualenv] 2025-12-01 00:28:00.149431 | controller | Collecting pytest-forked 2025-12-01 00:28:00.206278 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-01 00:28:00.264337 | controller | Collecting py 2025-12-01 00:28:00.269242 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-01 00:28:00.294294 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.7 MB/s eta 0:00:00 2025-12-01 00:28:00.466069 | controller | Collecting pytest>=3.10 2025-12-01 00:28:00.470514 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-12-01 00:28:00.492727 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 22.4 MB/s eta 0:00:00 2025-12-01 00:28:00.547884 | controller | Collecting iniconfig>=1.0.1 2025-12-01 00:28:00.557324 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-01 00:28:00.631705 | controller | Collecting packaging>=22 2025-12-01 00:28:00.636515 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-01 00:28:00.650685 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.1 MB/s eta 0:00:00 2025-12-01 00:28:00.697264 | controller | Collecting pluggy<2,>=1.5 2025-12-01 00:28:00.701478 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-01 00:28:00.774353 | controller | Collecting pygments>=2.7.2 2025-12-01 00:28:00.778506 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-01 00:28:00.803356 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 60.8 MB/s eta 0:00:00 2025-12-01 00:28:00.906439 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-01 00:28:03.361636 | 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.1 pytest-forked-1.6.0 2025-12-01 00:28:03.376660 | controller | 2025-12-01 00:28:03.598928 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-01 00:28:03.598988 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-01 00:28:04.041115 | controller | ok: Runtime: 0:00:04.146263 2025-12-01 00:28:04.050041 | 2025-12-01 00:28:04.050140 | TASK [Update pip] 2025-12-01 00:28:05.509540 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-01 00:28:05.810218 | controller | Collecting pip 2025-12-01 00:28:05.886014 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-01 00:28:05.947715 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 31.5 MB/s eta 0:00:00 2025-12-01 00:28:06.083928 | controller | Installing collected packages: pip 2025-12-01 00:28:06.084248 | controller | Attempting uninstall: pip 2025-12-01 00:28:06.089081 | controller | Found existing installation: pip 22.2.2 2025-12-01 00:28:06.418966 | controller | Uninstalling pip-22.2.2: 2025-12-01 00:28:06.450484 | controller | Successfully uninstalled pip-22.2.2 2025-12-01 00:28:08.375177 | controller | Successfully installed pip-25.3 2025-12-01 00:28:08.928529 | controller | ok: Runtime: 0:00:03.736400 2025-12-01 00:28:08.943178 | 2025-12-01 00:28:08.943332 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-01 00:28:09.852327 | controller | changed 2025-12-01 00:28:09.865830 | 2025-12-01 00:28:09.866028 | TASK [Install ansible into virtualenv] 2025-12-01 00:28:11.117740 | controller | Processing ./src/github.com/ansible/ansible 2025-12-01 00:28:11.124850 | controller | Installing build dependencies: started 2025-12-01 00:28:12.847516 | controller | Installing build dependencies: finished with status 'done' 2025-12-01 00:28:14.400740 | controller | Getting requirements to build wheel: started 2025-12-01 00:28:14.400797 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-01 00:28:15.283798 | controller | Preparing metadata (pyproject.toml): started 2025-12-01 00:28:15.283849 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-01 00:28:15.285357 | 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-01 00:28:15.290110 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-01 00:28:15.756637 | controller | ERROR 2025-12-01 00:28:15.757092 | controller | { 2025-12-01 00:28:15.757164 | controller | "delta": "0:00:04.943080", 2025-12-01 00:28:15.757207 | controller | "end": "2025-12-01 00:28:15.449397", 2025-12-01 00:28:15.757245 | controller | "msg": "non-zero return code", 2025-12-01 00:28:15.757298 | controller | "rc": 1, 2025-12-01 00:28:15.757342 | controller | "start": "2025-12-01 00:28:10.506317" 2025-12-01 00:28:15.757394 | controller | } failure 2025-12-01 00:28:15.760749 | 2025-12-01 00:28:15.760855 | PLAY RECAP 2025-12-01 00:28:15.760942 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-01 00:28:15.760984 | 2025-12-01 00:28:15.925520 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-01 00:28:15.926527 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-01 00:28:16.534895 | 2025-12-01 00:28:16.535029 | PLAY [all] 2025-12-01 00:28:16.557130 | 2025-12-01 00:28:16.557261 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-01 00:28:18.447839 | controller | changed: non-zero return code 2025-12-01 00:28:18.456928 | 2025-12-01 00:28:18.457068 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-01 00:28:18.482498 | controller | skipping: Conditional result was False 2025-12-01 00:28:18.491281 | 2025-12-01 00:28:18.491402 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-01 00:28:18.527464 | 2025-12-01 00:28:18.527705 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-01 00:28:18.564835 | 2025-12-01 00:28:18.565161 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-01 00:28:18.592350 | controller | skipping: Conditional result was False 2025-12-01 00:28:18.601440 | 2025-12-01 00:28:18.601611 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-01 00:28:18.642650 | 2025-12-01 00:28:18.642830 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-01 00:28:18.668253 | controller | skipping: Conditional result was False 2025-12-01 00:28:18.677458 | 2025-12-01 00:28:18.677567 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-01 00:28:18.702795 | controller | skipping: Conditional result was False 2025-12-01 00:28:18.710866 | 2025-12-01 00:28:18.710954 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-01 00:28:18.735635 | controller | skipping: Conditional result was False 2025-12-01 00:28:18.772484 | 2025-12-01 00:28:18.772571 | PLAY RECAP 2025-12-01 00:28:18.772634 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-01 00:28:18.772669 | 2025-12-01 00:28:18.876327 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-01 00:28:18.877231 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-01 00:28:19.451016 | 2025-12-01 00:28:19.451141 | PLAY [all:!appliance*] 2025-12-01 00:28:19.473106 | 2025-12-01 00:28:19.473241 | TASK [unregister the node] 2025-12-01 00:28:19.826127 | controller | skipping: Conditional result was False 2025-12-01 00:28:19.839201 | 2025-12-01 00:28:19.839376 | TASK [include_role : fetch-output] 2025-12-01 00:28:19.891379 | controller | ok 2025-12-01 00:28:19.926816 | 2025-12-01 00:28:19.926980 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-01 00:28:19.994857 | controller | skipping: Conditional result was False 2025-12-01 00:28:20.008633 | 2025-12-01 00:28:20.008812 | TASK [fetch-output : Set log path for single node] 2025-12-01 00:28:20.058295 | controller | ok 2025-12-01 00:28:20.070177 | 2025-12-01 00:28:20.070322 | LOOP [fetch-output : Ensure local output dirs] 2025-12-01 00:28:20.524917 | controller -> localhost | ok: "/var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/work/logs" 2025-12-01 00:28:20.793012 | controller -> localhost | changed: "/var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/work/artifacts" 2025-12-01 00:28:21.066425 | controller -> localhost | changed: "/var/lib/zuul/builds/a984c2db4042451c9a248b05668d1788/work/docs" 2025-12-01 00:28:21.078233 | 2025-12-01 00:28:21.078334 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-01 00:28:23.375582 | controller | changed: 2025-12-01 00:28:23.376070 | controller | .d..t...... ./ 2025-12-01 00:28:23.376166 | controller | cd+++++++++ controller/ 2025-12-01 00:28:23.376268 | controller | changed: All items complete 2025-12-01 00:28:23.376338 | 2025-12-01 00:28:25.439758 | controller | changed: .d..t...... ./ 2025-12-01 00:28:27.501809 | controller | changed: .d..t...... ./ 2025-12-01 00:28:27.535542 | 2025-12-01 00:28:27.535834 | TASK [include_role : fetch-output-openshift] 2025-12-01 00:28:27.565441 | controller | skipping: Conditional result was False 2025-12-01 00:28:27.584423 | 2025-12-01 00:28:27.584769 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-01 00:28:27.628633 | controller | skipping: Conditional result was False 2025-12-01 00:28:27.639729 | controller | skipping: Conditional result was False 2025-12-01 00:28:27.698528 | 2025-12-01 00:28:27.698753 | PLAY [localhost] 2025-12-01 00:28:27.719735 | 2025-12-01 00:28:27.719891 | TASK [Run Zuul manifest role] 2025-12-01 00:28:27.752588 | localhost | ok 2025-12-01 00:28:27.772419 | 2025-12-01 00:28:27.772834 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-01 00:28:28.249085 | localhost | changed 2025-12-01 00:28:28.262205 | 2025-12-01 00:28:28.262776 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-01 00:28:28.324664 | localhost | ok 2025-12-01 00:28:28.348899 | 2025-12-01 00:28:28.349067 | TASK [Set zuul-log-path fact] 2025-12-01 00:28:28.418311 | localhost | ok 2025-12-01 00:28:28.435803 | 2025-12-01 00:28:28.435895 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-01 00:28:28.478740 | localhost | ok 2025-12-01 00:28:28.489744 | 2025-12-01 00:28:28.489818 | LOOP [Run upload-logs-swift role] 2025-12-01 00:28:28.537511 | localhost | Output suppressed because no_log was given 2025-12-01 00:28:28.576448 | 2025-12-01 00:28:28.576614 | TASK [Set zuul-log-path fact] 2025-12-01 00:28:28.602729 | localhost | skipping: Conditional result was False 2025-12-01 00:28:28.610559 | 2025-12-01 00:28:28.610646 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-01 00:28:29.063186 | localhost -> localhost | ok: Runtime: 0:00:00.006746 2025-12-01 00:28:29.069347 | 2025-12-01 00:28:29.069413 | TASK [upload-logs-swift : Upload logs to swift]