2025-11-11 00:21:07.690286 | Job console starting... 2025-11-11 00:21:07.704611 | Updating repositories 2025-11-11 00:21:07.879102 | Preparing job workspace 2025-11-11 00:21:12.193753 | Running Ansible setup... 2025-11-11 00:21:19.433032 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-11 00:21:20.042635 | 2025-11-11 00:21:20.042774 | PLAY [localhost] 2025-11-11 00:21:20.051289 | 2025-11-11 00:21:20.051362 | TASK [Gathering Facts] 2025-11-11 00:21:21.037081 | localhost | ok 2025-11-11 00:21:21.063519 | 2025-11-11 00:21:21.063657 | TASK [Setup log path fact] 2025-11-11 00:21:21.081925 | localhost | ok 2025-11-11 00:21:21.094321 | 2025-11-11 00:21:21.094395 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-11 00:21:21.131528 | localhost | ok 2025-11-11 00:21:21.139995 | 2025-11-11 00:21:21.140075 | TASK [emit-job-header : Print job information] 2025-11-11 00:21:21.190419 | # Job Information 2025-11-11 00:21:21.190628 | Ansible Version: 2.15.12 2025-11-11 00:21:21.190697 | Job: ansible-test-sanity-docker-milestone 2025-11-11 00:21:21.190735 | Pipeline: periodic 2025-11-11 00:21:21.190763 | Executor: ze02.softwarefactory-project.io 2025-11-11 00:21:21.190788 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-11 00:21:21.190817 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/af7/ansible/af72729854694c1986d23d86a0d04eed/ 2025-11-11 00:21:21.190844 | Event ID: 227e4e6828f94fb3a69b0e687d5dfdf5 2025-11-11 00:21:21.196604 | 2025-11-11 00:21:21.196721 | LOOP [emit-job-header : Print node information] 2025-11-11 00:21:21.320785 | localhost | ok: 2025-11-11 00:21:21.320979 | localhost | # Node Information 2025-11-11 00:21:21.321015 | localhost | Inventory Hostname: controller 2025-11-11 00:21:21.321043 | localhost | Hostname: np0005517402 2025-11-11 00:21:21.321069 | localhost | Username: zuul 2025-11-11 00:21:21.321100 | localhost | Distro: Fedora 37 2025-11-11 00:21:21.321126 | localhost | Provider: ansible-vexxhost-ams1 2025-11-11 00:21:21.321150 | localhost | Region: ams1 2025-11-11 00:21:21.321173 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-11 00:21:21.321197 | localhost | Product Name: OpenStack Nova 2025-11-11 00:21:21.321221 | localhost | Interface IP: 38.129.16.236 2025-11-11 00:21:21.335459 | 2025-11-11 00:21:21.335557 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-11 00:21:21.739099 | localhost -> localhost | changed 2025-11-11 00:21:21.744400 | 2025-11-11 00:21:21.744469 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-11 00:21:22.754854 | localhost -> localhost | changed 2025-11-11 00:21:22.788473 | 2025-11-11 00:21:22.788577 | PLAY [all:!appliance*] 2025-11-11 00:21:22.811297 | 2025-11-11 00:21:22.811447 | TASK [include_role : start-zuul-console] 2025-11-11 00:21:22.835320 | controller | ok 2025-11-11 00:21:22.854197 | 2025-11-11 00:21:22.854293 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-11 00:21:23.908733 | controller | ok 2025-11-11 00:21:23.919996 | 2025-11-11 00:21:23.920062 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-11 00:21:26.578074 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-11 00:21:26.593313 | 2025-11-11 00:21:26.593482 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-11 00:21:26.965318 | controller | skipping: Conditional result was False 2025-11-11 00:21:26.977250 | 2025-11-11 00:21:26.977349 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-11 00:21:27.003288 | controller | skipping: Conditional result was False 2025-11-11 00:21:27.022154 | 2025-11-11 00:21:27.022323 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-11 00:21:27.048961 | controller | skipping: Conditional result was False 2025-11-11 00:21:27.060547 | 2025-11-11 00:21:27.060645 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-11 00:21:27.087213 | controller | skipping: Conditional result was False 2025-11-11 00:21:27.102800 | 2025-11-11 00:21:27.103013 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-11 00:21:27.130968 | controller | skipping: Conditional result was False 2025-11-11 00:21:27.140215 | 2025-11-11 00:21:27.140314 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-11 00:21:27.165985 | controller | skipping: Conditional result was False 2025-11-11 00:21:27.183056 | 2025-11-11 00:21:27.183163 | TASK [Disable Fedora Modular] 2025-11-11 00:21:28.351357 | controller | changed 2025-11-11 00:21:28.364987 | 2025-11-11 00:21:28.365130 | TASK [Enable EPEL] 2025-11-11 00:21:28.393312 | controller | skipping: Conditional result was False 2025-11-11 00:21:28.408529 | 2025-11-11 00:21:28.408770 | TASK [Register the RHEL node] 2025-11-11 00:21:28.819188 | 2025-11-11 00:21:28.819548 | TASK [Show the subscription-manager status] 2025-11-11 00:21:29.212062 | controller | skipping: Conditional result was False 2025-11-11 00:21:29.228613 | 2025-11-11 00:21:29.228869 | TASK [Enable EPEL on RHEL] 2025-11-11 00:21:29.641056 | controller | skipping: Conditional result was False 2025-11-11 00:21:29.656332 | 2025-11-11 00:21:29.656503 | TASK [Install git and tox] 2025-11-11 00:23:38.680634 | controller | changed 2025-11-11 00:23:38.697284 | 2025-11-11 00:23:38.697505 | TASK [include_role : prepare-workspace] 2025-11-11 00:23:38.738245 | controller | ok 2025-11-11 00:23:38.777089 | 2025-11-11 00:23:38.777283 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-11 00:23:39.618397 | controller | ok 2025-11-11 00:23:39.632758 | 2025-11-11 00:23:39.632893 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-11 00:23:55.090526 | controller | Output suppressed because no_log was given 2025-11-11 00:23:55.100615 | 2025-11-11 00:23:55.100739 | TASK [include_role : prepare-workspace-openshift] 2025-11-11 00:23:55.125030 | controller | skipping: Conditional result was False 2025-11-11 00:23:55.174909 | 2025-11-11 00:23:55.174985 | PLAY [all:!appliance] 2025-11-11 00:23:55.190958 | 2025-11-11 00:23:55.191111 | TASK [Run add-build-sshkey role (RSA)] 2025-11-11 00:23:55.220631 | controller | ok 2025-11-11 00:23:55.235591 | 2025-11-11 00:23:55.235678 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-11 00:23:55.484903 | controller -> localhost | ok 2025-11-11 00:23:55.498523 | 2025-11-11 00:23:55.498743 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-11 00:23:55.539868 | controller | ok 2025-11-11 00:23:55.571222 | controller | included: /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-11 00:23:55.579617 | 2025-11-11 00:23:55.579739 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-11 00:23:56.170390 | controller -> localhost | Generating public/private rsa key pair. 2025-11-11 00:23:56.170811 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/work/af72729854694c1986d23d86a0d04eed_id_rsa. 2025-11-11 00:23:56.170883 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/work/af72729854694c1986d23d86a0d04eed_id_rsa.pub. 2025-11-11 00:23:56.170938 | controller -> localhost | The key fingerprint is: 2025-11-11 00:23:56.170995 | controller -> localhost | SHA256:K6yN5zNMFaXGZ++sAfoxKiA6cQxvqkO465lBDuO1G2w zuul-build-sshkey 2025-11-11 00:23:56.171045 | controller -> localhost | The key's randomart image is: 2025-11-11 00:23:56.171094 | controller -> localhost | +---[RSA 2048]----+ 2025-11-11 00:23:56.171141 | controller -> localhost | | .. | 2025-11-11 00:23:56.171189 | controller -> localhost | | ... | 2025-11-11 00:23:56.171236 | controller -> localhost | | +.o | 2025-11-11 00:23:56.171282 | controller -> localhost | |. ..o . | 2025-11-11 00:23:56.171873 | controller -> localhost | |+= . .S . | 2025-11-11 00:23:56.172004 | controller -> localhost | |OoO .... o o | 2025-11-11 00:23:56.172074 | controller -> localhost | |o@ E o+ + . o | 2025-11-11 00:23:56.172131 | controller -> localhost | |* = ++=+ o o | 2025-11-11 00:23:56.172225 | controller -> localhost | |=B .o++o. . | 2025-11-11 00:23:56.172281 | controller -> localhost | +----[SHA256]-----+ 2025-11-11 00:23:56.172396 | controller -> localhost | ok: Runtime: 0:00:00.162405 2025-11-11 00:23:56.188185 | 2025-11-11 00:23:56.188343 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-11 00:23:56.220348 | controller | ok 2025-11-11 00:23:56.242248 | controller | included: /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-11 00:23:56.256282 | 2025-11-11 00:23:56.256428 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-11 00:23:56.282502 | controller | skipping: Conditional result was False 2025-11-11 00:23:56.292766 | 2025-11-11 00:23:56.292885 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-11 00:23:57.396185 | controller | changed 2025-11-11 00:23:57.409377 | 2025-11-11 00:23:57.409523 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-11 00:23:58.060918 | controller | ok 2025-11-11 00:23:58.074078 | 2025-11-11 00:23:58.074218 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-11 00:24:01.212156 | controller | changed 2025-11-11 00:24:01.220409 | 2025-11-11 00:24:01.220508 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-11 00:24:04.310179 | controller | changed 2025-11-11 00:24:04.323104 | 2025-11-11 00:24:04.323243 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-11 00:24:04.350845 | controller | skipping: Conditional result was False 2025-11-11 00:24:04.365362 | 2025-11-11 00:24:04.365502 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-11 00:24:04.789904 | controller -> localhost | changed 2025-11-11 00:24:04.802268 | 2025-11-11 00:24:04.802362 | TASK [add-build-sshkey : Add back temp key] 2025-11-11 00:24:05.123774 | controller -> localhost | Identity added: /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/work/af72729854694c1986d23d86a0d04eed_id_rsa (zuul-build-sshkey) 2025-11-11 00:24:05.124261 | controller -> localhost | ok: Runtime: 0:00:00.014216 2025-11-11 00:24:05.138086 | 2025-11-11 00:24:05.138221 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-11 00:24:06.144727 | controller | ok 2025-11-11 00:24:06.156700 | 2025-11-11 00:24:06.156837 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-11 00:24:06.202868 | controller | skipping: Conditional result was False 2025-11-11 00:24:06.232923 | 2025-11-11 00:24:06.233059 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-11 00:24:06.265786 | controller | ok 2025-11-11 00:24:06.288074 | 2025-11-11 00:24:06.288187 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-11 00:24:06.567627 | controller -> localhost | ok 2025-11-11 00:24:06.578983 | 2025-11-11 00:24:06.579128 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-11 00:24:06.612115 | controller | ok 2025-11-11 00:24:06.629164 | controller | included: /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-11 00:24:06.638952 | 2025-11-11 00:24:06.639097 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-11 00:24:06.961865 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-11 00:24:06.962409 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/work/af72729854694c1986d23d86a0d04eed_id_ecdsa. 2025-11-11 00:24:06.962474 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/work/af72729854694c1986d23d86a0d04eed_id_ecdsa.pub. 2025-11-11 00:24:06.962540 | controller -> localhost | The key fingerprint is: 2025-11-11 00:24:06.962585 | controller -> localhost | SHA256:Wa7syEJhlw9N7oPrQu8taAx7ivppXXxJ/hWX2I6hgkE zuul-build-sshkey 2025-11-11 00:24:06.962626 | controller -> localhost | The key's randomart image is: 2025-11-11 00:24:06.962693 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-11 00:24:06.962744 | controller -> localhost | | | 2025-11-11 00:24:06.962784 | controller -> localhost | | E . | 2025-11-11 00:24:06.962822 | controller -> localhost | | . = . o . | 2025-11-11 00:24:06.962858 | controller -> localhost | | o = ++ + + | 2025-11-11 00:24:06.962895 | controller -> localhost | | . + XS... * | 2025-11-11 00:24:06.962932 | controller -> localhost | | . o =.O.. o . | 2025-11-11 00:24:06.962968 | controller -> localhost | | B + oo+ . | 2025-11-11 00:24:06.963005 | controller -> localhost | | .o.O.++ . | 2025-11-11 00:24:06.963041 | controller -> localhost | |+o++ ==.o | 2025-11-11 00:24:06.963077 | controller -> localhost | +----[SHA256]-----+ 2025-11-11 00:24:06.963183 | controller -> localhost | ok: Runtime: 0:00:00.014812 2025-11-11 00:24:06.979601 | 2025-11-11 00:24:06.979789 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-11 00:24:07.025062 | controller | ok 2025-11-11 00:24:07.042231 | controller | included: /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-11 00:24:07.055622 | 2025-11-11 00:24:07.055813 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-11 00:24:07.084797 | controller | skipping: Conditional result was False 2025-11-11 00:24:07.106829 | 2025-11-11 00:24:07.107017 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-11 00:24:08.059996 | controller | changed 2025-11-11 00:24:08.113520 | 2025-11-11 00:24:08.113713 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-11 00:24:08.816617 | controller | ok 2025-11-11 00:24:08.830545 | 2025-11-11 00:24:08.830760 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-11 00:24:11.922658 | controller | changed 2025-11-11 00:24:11.935772 | 2025-11-11 00:24:11.935920 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-11 00:24:15.024001 | controller | changed 2025-11-11 00:24:15.039904 | 2025-11-11 00:24:15.040050 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-11 00:24:15.067117 | controller | skipping: Conditional result was False 2025-11-11 00:24:15.083987 | 2025-11-11 00:24:15.084288 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-11 00:24:15.376935 | controller -> localhost | changed 2025-11-11 00:24:15.402194 | 2025-11-11 00:24:15.402354 | TASK [add-build-sshkey : Add back temp key] 2025-11-11 00:24:15.684098 | controller -> localhost | Identity added: /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/work/af72729854694c1986d23d86a0d04eed_id_ecdsa (zuul-build-sshkey) 2025-11-11 00:24:15.684392 | controller -> localhost | ok: Runtime: 0:00:00.013966 2025-11-11 00:24:15.691187 | 2025-11-11 00:24:15.691250 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-11 00:24:16.432762 | controller | ok 2025-11-11 00:24:16.445907 | 2025-11-11 00:24:16.446064 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-11 00:24:16.484078 | controller | skipping: Conditional result was False 2025-11-11 00:24:16.508565 | 2025-11-11 00:24:16.508730 | TASK [include_role : remove-zuul-sshkey] 2025-11-11 00:24:16.535890 | controller | skipping: Conditional result was False 2025-11-11 00:24:16.549534 | 2025-11-11 00:24:16.549704 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-11 00:24:17.254040 | controller | ok: "logs" 2025-11-11 00:24:17.254567 | controller | ok: All items complete 2025-11-11 00:24:17.254651 | 2025-11-11 00:24:17.932107 | controller | ok: "artifacts" 2025-11-11 00:24:18.592095 | controller | ok: "docs" 2025-11-11 00:24:18.613273 | 2025-11-11 00:24:18.613458 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-11 00:24:19.363444 | controller | changed: "logs" 2025-11-11 00:24:20.027138 | controller | changed: "artifacts" 2025-11-11 00:24:20.685649 | controller | changed: "docs" 2025-11-11 00:24:20.742232 | 2025-11-11 00:24:20.742358 | PLAY RECAP 2025-11-11 00:24:20.742417 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-11 00:24:20.742455 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-11 00:24:20.742483 | 2025-11-11 00:24:20.861494 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-11 00:24:20.865301 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-11 00:24:21.435593 | 2025-11-11 00:24:21.435740 | PLAY [all] 2025-11-11 00:24:21.457141 | 2025-11-11 00:24:21.457245 | TASK [Install binary dependencies] 2025-11-11 00:24:21.534271 | controller | ok 2025-11-11 00:24:21.564542 | 2025-11-11 00:24:21.564735 | TASK [bindep : Include find tasks] 2025-11-11 00:24:21.612606 | controller | ok 2025-11-11 00:24:21.629159 | controller | included: /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-11 00:24:21.637738 | 2025-11-11 00:24:21.637827 | TASK [bindep : Look for bindep.txt] 2025-11-11 00:24:22.700143 | controller | ok 2025-11-11 00:24:22.712776 | 2025-11-11 00:24:22.712922 | TASK [bindep : Define bindep_file fact] 2025-11-11 00:24:22.740559 | controller | skipping: Conditional result was False 2025-11-11 00:24:22.753404 | 2025-11-11 00:24:22.753547 | TASK [bindep : Look for other-requirements.txt] 2025-11-11 00:24:23.396382 | controller | ok 2025-11-11 00:24:23.411124 | 2025-11-11 00:24:23.411272 | TASK [bindep : Define bindep_file fact] 2025-11-11 00:24:23.449740 | controller | skipping: Conditional result was False 2025-11-11 00:24:23.464449 | 2025-11-11 00:24:23.464605 | TASK [bindep : Look for bindep fallback file] 2025-11-11 00:24:23.503047 | controller | skipping: Conditional result was False 2025-11-11 00:24:23.518467 | 2025-11-11 00:24:23.518623 | TASK [bindep : Define bindep_file fact] 2025-11-11 00:24:23.546030 | controller | skipping: Conditional result was False 2025-11-11 00:24:23.560523 | 2025-11-11 00:24:23.560719 | TASK [bindep : Include bindep tasks] 2025-11-11 00:24:23.588174 | controller | skipping: Conditional result was False 2025-11-11 00:24:23.603038 | 2025-11-11 00:24:23.603213 | TASK [bindep : Include install tasks] 2025-11-11 00:24:23.631000 | controller | skipping: Conditional result was False 2025-11-11 00:24:23.650245 | 2025-11-11 00:24:23.650530 | LOOP [bindep : Include package tasks] 2025-11-11 00:24:23.729592 | 2025-11-11 00:24:23.729857 | TASK [Run test-setup role] 2025-11-11 00:24:23.754343 | controller | ok 2025-11-11 00:24:23.780209 | 2025-11-11 00:24:23.780314 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-11 00:24:24.502157 | controller | ok 2025-11-11 00:24:24.517111 | 2025-11-11 00:24:24.517258 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-11 00:24:24.906248 | controller | skipping: Conditional result was False 2025-11-11 00:24:24.959701 | 2025-11-11 00:24:24.959789 | PLAY RECAP 2025-11-11 00:24:24.959842 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-11 00:24:24.959869 | 2025-11-11 00:24:25.058049 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-11 00:24:25.059898 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-11 00:24:25.710445 | 2025-11-11 00:24:25.710589 | PLAY [controller] 2025-11-11 00:24:25.731727 | 2025-11-11 00:24:25.731885 | TASK [Create the /root directory] 2025-11-11 00:24:26.871355 | controller | ok 2025-11-11 00:24:26.883531 | 2025-11-11 00:24:26.883714 | TASK [Install glibc-langpack-en] 2025-11-11 00:24:34.876481 | controller | ok: Nothing to do 2025-11-11 00:24:34.888614 | 2025-11-11 00:24:34.888787 | TASK [Ensure controller directory exists] 2025-11-11 00:24:35.703201 | controller | changed 2025-11-11 00:24:35.715729 | 2025-11-11 00:24:35.715899 | TASK [Install container runtime] 2025-11-11 00:24:35.797792 | controller | ok 2025-11-11 00:24:35.859046 | 2025-11-11 00:24:35.859190 | LOOP [ensure-podman : Find distribution installation] 2025-11-11 00:24:35.901531 | controller | ok: "/var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-11 00:24:35.915789 | controller | included: /var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-11 00:24:35.922533 | 2025-11-11 00:24:35.922631 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-11 00:26:36.720071 | controller | changed 2025-11-11 00:26:36.726962 | 2025-11-11 00:26:36.727023 | TASK [ensure-podman : Fetch podman version] 2025-11-11 00:26:37.977592 | controller | Client: Podman Engine 2025-11-11 00:26:37.977795 | controller | Version: 4.6.2 2025-11-11 00:26:37.977854 | controller | API Version: 4.6.2 2025-11-11 00:26:37.977898 | controller | Go Version: go1.19.12 2025-11-11 00:26:37.977984 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-11 00:26:37.978028 | controller | OS/Arch: linux/amd64 2025-11-11 00:26:38.582632 | controller | ok: Runtime: 0:00:00.374435 2025-11-11 00:26:38.597452 | 2025-11-11 00:26:38.597642 | TASK [ensure-podman : Print podman version installed] 2025-11-11 00:26:38.637338 | Podman version: Client: Podman Engine 2025-11-11 00:26:38.637596 | Version: 4.6.2 2025-11-11 00:26:38.637655 | API Version: 4.6.2 2025-11-11 00:26:38.637736 | Go Version: go1.19.12 2025-11-11 00:26:38.637777 | Built: Mon Aug 28 19:38:31 2023 2025-11-11 00:26:38.637817 | OS/Arch: linux/amd64 2025-11-11 00:26:38.668573 | 2025-11-11 00:26:38.668714 | TASK [ensure-podman : Validate podman engine] 2025-11-11 00:26:39.034377 | controller | skipping: Conditional result was False 2025-11-11 00:26:39.048055 | 2025-11-11 00:26:39.048231 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-11 00:26:39.064837 | controller | skipping: Conditional result was False 2025-11-11 00:26:39.088205 | 2025-11-11 00:26:39.088341 | TASK [Ensure python3.8 is present] 2025-11-11 00:26:39.105117 | controller | skipping: Conditional result was False 2025-11-11 00:26:39.119178 | 2025-11-11 00:26:39.119330 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-11 00:26:39.154938 | controller | ok 2025-11-11 00:26:39.194859 | 2025-11-11 00:26:39.194983 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-11 00:26:42.548762 | controller | ok: Nothing to do 2025-11-11 00:26:42.554393 | 2025-11-11 00:26:42.554455 | TASK [our-ensure-python : Also install python3-devel] 2025-11-11 00:26:57.963423 | controller | changed 2025-11-11 00:26:57.979532 | 2025-11-11 00:26:57.979726 | TASK [Run ensure-virtualenv role] 2025-11-11 00:26:58.004804 | controller | ok 2025-11-11 00:26:58.028194 | 2025-11-11 00:26:58.028287 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-11 00:26:58.841236 | controller | /usr/bin/virtualenv 2025-11-11 00:26:59.410656 | controller | ok: Runtime: 0:00:00.006250 2025-11-11 00:26:59.420177 | 2025-11-11 00:26:59.420288 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-11 00:26:59.455048 | controller | skipping: Conditional result was False 2025-11-11 00:26:59.455488 | controller | ok: All items complete 2025-11-11 00:26:59.455546 | 2025-11-11 00:26:59.482126 | 2025-11-11 00:26:59.482303 | TASK [Find the full path of the Python interpreter] 2025-11-11 00:27:00.291035 | controller | /usr/bin/python3 2025-11-11 00:27:00.862199 | controller | ok 2025-11-11 00:27:00.874854 | 2025-11-11 00:27:00.874989 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-11 00:27:02.723850 | controller | created virtual environment CPython3.11.0.final.0-64 in 882ms 2025-11-11 00:27:02.776299 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-11 00:27:02.776356 | 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-11-11 00:27:02.776381 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-11 00:27:02.776401 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-11 00:27:03.254411 | controller | changed 2025-11-11 00:27:03.268133 | 2025-11-11 00:27:03.268279 | TASK [Set selinux package] 2025-11-11 00:27:03.307939 | controller | ok 2025-11-11 00:27:03.319710 | 2025-11-11 00:27:03.319845 | TASK [Set selinux package (Fedora)] 2025-11-11 00:27:03.371180 | controller | ok 2025-11-11 00:27:03.381936 | 2025-11-11 00:27:03.382060 | TASK [Install selinux into virtualenv] 2025-11-11 00:27:06.287803 | controller | Collecting selinux-please-lie-to-me 2025-11-11 00:27:06.352079 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-11 00:27:06.898148 | controller | Collecting setuptools<50.0.0 2025-11-11 00:27:06.906117 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-11 00:27:06.957890 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 17.3 MB/s eta 0:00:00 2025-11-11 00:27:07.105558 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-11 00:27:07.105879 | controller | Attempting uninstall: setuptools 2025-11-11 00:27:07.109652 | controller | Found existing installation: setuptools 62.6.0 2025-11-11 00:27:07.214161 | controller | Uninstalling setuptools-62.6.0: 2025-11-11 00:27:07.227382 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-11 00:27:07.965285 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-11 00:27:08.166003 | controller | 2025-11-11 00:27:08.431950 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-11 00:27:08.432002 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-11 00:27:08.784285 | controller | ok: Runtime: 0:00:04.263463 2025-11-11 00:27:08.797585 | 2025-11-11 00:27:08.797779 | TASK [Install pytest-forked into virtualenv] 2025-11-11 00:27:10.291610 | controller | Collecting pytest-forked 2025-11-11 00:27:10.356442 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-11 00:27:10.419207 | controller | Collecting py 2025-11-11 00:27:10.424551 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-11 00:27:10.456060 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00 2025-11-11 00:27:10.624487 | controller | Collecting pytest>=3.10 2025-11-11 00:27:10.629569 | controller | Downloading pytest-9.0.0-py3-none-any.whl (373 kB) 2025-11-11 00:27:10.653947 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.4/373.4 kB 23.0 MB/s eta 0:00:00 2025-11-11 00:27:10.703574 | controller | Collecting iniconfig>=1.0.1 2025-11-11 00:27:10.708242 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-11 00:27:10.772208 | controller | Collecting packaging>=22 2025-11-11 00:27:10.776814 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-11 00:27:10.789074 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.8 MB/s eta 0:00:00 2025-11-11 00:27:10.858156 | controller | Collecting pluggy<2,>=1.5 2025-11-11 00:27:10.862576 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-11 00:27:10.928991 | controller | Collecting pygments>=2.7.2 2025-11-11 00:27:10.933664 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-11 00:27:10.971419 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 37.3 MB/s eta 0:00:00 2025-11-11 00:27:11.104963 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-11 00:27:13.495244 | 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.0 pytest-forked-1.6.0 2025-11-11 00:27:13.509898 | controller | 2025-11-11 00:27:13.733302 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-11 00:27:13.733338 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-11 00:27:14.194334 | controller | ok: Runtime: 0:00:04.160001 2025-11-11 00:27:14.206220 | 2025-11-11 00:27:14.206332 | TASK [Update pip] 2025-11-11 00:27:15.620141 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-11 00:27:15.895411 | controller | Collecting pip 2025-11-11 00:27:15.978346 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-11 00:27:16.063594 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 22.4 MB/s eta 0:00:00 2025-11-11 00:27:16.159602 | controller | Installing collected packages: pip 2025-11-11 00:27:16.159947 | controller | Attempting uninstall: pip 2025-11-11 00:27:16.164252 | controller | Found existing installation: pip 22.2.2 2025-11-11 00:27:16.405336 | controller | Uninstalling pip-22.2.2: 2025-11-11 00:27:16.431404 | controller | Successfully uninstalled pip-22.2.2 2025-11-11 00:27:18.191304 | controller | Successfully installed pip-25.3 2025-11-11 00:27:18.590839 | controller | ok: Runtime: 0:00:03.387656 2025-11-11 00:27:18.603329 | 2025-11-11 00:27:18.603461 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-11 00:27:19.471093 | controller | changed 2025-11-11 00:27:19.483900 | 2025-11-11 00:27:19.484036 | TASK [Install ansible into virtualenv] 2025-11-11 00:27:20.749319 | controller | Processing ./src/github.com/ansible/ansible 2025-11-11 00:27:20.754383 | controller | Installing build dependencies: started 2025-11-11 00:27:22.682037 | controller | Installing build dependencies: finished with status 'done' 2025-11-11 00:27:22.682538 | controller | Getting requirements to build wheel: started 2025-11-11 00:27:24.175011 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-11 00:27:24.176154 | controller | Preparing metadata (pyproject.toml): started 2025-11-11 00:27:25.076616 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-11 00:27:25.080039 | 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-11-11 00:27:25.084289 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-11 00:27:25.391327 | controller | ERROR 2025-11-11 00:27:25.391561 | controller | { 2025-11-11 00:27:25.391622 | controller | "delta": "0:00:05.061307", 2025-11-11 00:27:25.391702 | controller | "end": "2025-11-11 00:27:25.262858", 2025-11-11 00:27:25.391753 | controller | "msg": "non-zero return code", 2025-11-11 00:27:25.391807 | controller | "rc": 1, 2025-11-11 00:27:25.391845 | controller | "start": "2025-11-11 00:27:20.201551" 2025-11-11 00:27:25.391881 | controller | } failure 2025-11-11 00:27:25.394082 | 2025-11-11 00:27:25.394175 | PLAY RECAP 2025-11-11 00:27:25.394254 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-11 00:27:25.394297 | 2025-11-11 00:27:25.505390 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-11 00:27:25.507315 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-11 00:27:26.060067 | 2025-11-11 00:27:26.060174 | PLAY [all] 2025-11-11 00:27:26.081222 | 2025-11-11 00:27:26.081320 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-11 00:27:27.940345 | controller | changed: non-zero return code 2025-11-11 00:27:27.954708 | 2025-11-11 00:27:27.954903 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-11 00:27:27.982614 | controller | skipping: Conditional result was False 2025-11-11 00:27:27.997063 | 2025-11-11 00:27:27.997383 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-11 00:27:28.040841 | 2025-11-11 00:27:28.041128 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-11 00:27:28.083042 | 2025-11-11 00:27:28.083378 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-11 00:27:28.111016 | controller | skipping: Conditional result was False 2025-11-11 00:27:28.125511 | 2025-11-11 00:27:28.125742 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-11 00:27:28.167486 | 2025-11-11 00:27:28.167815 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-11 00:27:28.195242 | controller | skipping: Conditional result was False 2025-11-11 00:27:28.209265 | 2025-11-11 00:27:28.209416 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-11 00:27:28.236749 | controller | skipping: Conditional result was False 2025-11-11 00:27:28.251017 | 2025-11-11 00:27:28.251156 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-11 00:27:28.278426 | controller | skipping: Conditional result was False 2025-11-11 00:27:28.328889 | 2025-11-11 00:27:28.329017 | PLAY RECAP 2025-11-11 00:27:28.329074 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-11 00:27:28.329102 | 2025-11-11 00:27:28.452207 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-11 00:27:28.453962 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-11 00:27:29.013747 | 2025-11-11 00:27:29.013887 | PLAY [all:!appliance*] 2025-11-11 00:27:29.041828 | 2025-11-11 00:27:29.041957 | TASK [unregister the node] 2025-11-11 00:27:29.402417 | controller | skipping: Conditional result was False 2025-11-11 00:27:29.410401 | 2025-11-11 00:27:29.410504 | TASK [include_role : fetch-output] 2025-11-11 00:27:29.453962 | controller | ok 2025-11-11 00:27:29.478943 | 2025-11-11 00:27:29.479049 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-11 00:27:29.554024 | controller | skipping: Conditional result was False 2025-11-11 00:27:29.560225 | 2025-11-11 00:27:29.560303 | TASK [fetch-output : Set log path for single node] 2025-11-11 00:27:29.599933 | controller | ok 2025-11-11 00:27:29.605489 | 2025-11-11 00:27:29.605558 | LOOP [fetch-output : Ensure local output dirs] 2025-11-11 00:27:30.018121 | controller -> localhost | ok: "/var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/work/logs" 2025-11-11 00:27:30.224101 | controller -> localhost | changed: "/var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/work/artifacts" 2025-11-11 00:27:30.472435 | controller -> localhost | changed: "/var/lib/zuul/builds/af72729854694c1986d23d86a0d04eed/work/docs" 2025-11-11 00:27:30.488476 | 2025-11-11 00:27:30.488583 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-11 00:27:32.700905 | controller | changed: 2025-11-11 00:27:32.701232 | controller | .d..t...... ./ 2025-11-11 00:27:32.701306 | controller | cd+++++++++ controller/ 2025-11-11 00:27:32.701384 | controller | changed: All items complete 2025-11-11 00:27:32.701439 | 2025-11-11 00:27:34.789438 | controller | changed: .d..t...... ./ 2025-11-11 00:27:36.890270 | controller | changed: .d..t...... ./ 2025-11-11 00:27:36.907939 | 2025-11-11 00:27:36.908071 | TASK [include_role : fetch-output-openshift] 2025-11-11 00:27:36.923136 | controller | skipping: Conditional result was False 2025-11-11 00:27:36.932245 | 2025-11-11 00:27:36.932349 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-11 00:27:36.960186 | controller | skipping: Conditional result was False 2025-11-11 00:27:36.968004 | controller | skipping: Conditional result was False 2025-11-11 00:27:37.016759 | 2025-11-11 00:27:37.016964 | PLAY [localhost] 2025-11-11 00:27:37.035267 | 2025-11-11 00:27:37.035385 | TASK [Run Zuul manifest role] 2025-11-11 00:27:37.056564 | localhost | ok 2025-11-11 00:27:37.075677 | 2025-11-11 00:27:37.075811 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-11 00:27:37.429365 | localhost | changed 2025-11-11 00:27:37.434318 | 2025-11-11 00:27:37.434411 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-11 00:27:37.475870 | localhost | ok 2025-11-11 00:27:37.488236 | 2025-11-11 00:27:37.488322 | TASK [Set zuul-log-path fact] 2025-11-11 00:27:37.510153 | localhost | ok 2025-11-11 00:27:37.550949 | 2025-11-11 00:27:37.551057 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-11 00:27:37.590475 | localhost | ok 2025-11-11 00:27:37.601125 | 2025-11-11 00:27:37.601203 | LOOP [Run upload-logs-swift role] 2025-11-11 00:27:37.647593 | localhost | Output suppressed because no_log was given 2025-11-11 00:27:37.690393 | 2025-11-11 00:27:37.690478 | TASK [Set zuul-log-path fact] 2025-11-11 00:27:37.726275 | localhost | skipping: Conditional result was False 2025-11-11 00:27:37.740754 | 2025-11-11 00:27:37.740938 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-11 00:27:38.171378 | localhost -> localhost | ok: Runtime: 0:00:00.006263 2025-11-11 00:27:38.183041 | 2025-11-11 00:27:38.183183 | TASK [upload-logs-swift : Upload logs to swift]