2025-09-28 00:12:05.154203 | Job console starting... 2025-09-28 00:12:05.166032 | Updating repositories 2025-09-28 00:12:05.270392 | Preparing job workspace 2025-09-28 00:12:09.112544 | Running Ansible setup... 2025-09-28 00:12:17.592097 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-28 00:12:18.186523 | 2025-09-28 00:12:18.186651 | PLAY [localhost] 2025-09-28 00:12:18.195428 | 2025-09-28 00:12:18.195510 | TASK [Gathering Facts] 2025-09-28 00:12:19.168078 | localhost | ok 2025-09-28 00:12:19.182160 | 2025-09-28 00:12:19.182288 | TASK [Setup log path fact] 2025-09-28 00:12:19.199700 | localhost | ok 2025-09-28 00:12:19.211974 | 2025-09-28 00:12:19.212081 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-28 00:12:19.239786 | localhost | ok 2025-09-28 00:12:19.247621 | 2025-09-28 00:12:19.247735 | TASK [emit-job-header : Print job information] 2025-09-28 00:12:19.275305 | # Job Information 2025-09-28 00:12:19.275449 | Ansible Version: 2.15.12 2025-09-28 00:12:19.275481 | Job: ansible-test-sanity-docker-milestone 2025-09-28 00:12:19.275508 | Pipeline: periodic 2025-09-28 00:12:19.275531 | Executor: ze04.softwarefactory-project.io 2025-09-28 00:12:19.275553 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-09-28 00:12:19.275578 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/da5/ansible/da53e2e30aab42e3aaddcee46fd0cf71/ 2025-09-28 00:12:19.275601 | Event ID: ac2a50b5a9f846e4a242a91e1fee7f50 2025-09-28 00:12:19.279229 | 2025-09-28 00:12:19.279291 | LOOP [emit-job-header : Print node information] 2025-09-28 00:12:19.375176 | localhost | ok: 2025-09-28 00:12:19.375470 | localhost | # Node Information 2025-09-28 00:12:19.375514 | localhost | Inventory Hostname: controller 2025-09-28 00:12:19.375544 | localhost | Hostname: np0005457729 2025-09-28 00:12:19.375572 | localhost | Username: zuul 2025-09-28 00:12:19.375607 | localhost | Distro: Fedora 37 2025-09-28 00:12:19.375636 | localhost | Provider: ansible-vexxhost-ams1 2025-09-28 00:12:19.375663 | localhost | Region: ams1 2025-09-28 00:12:19.375713 | localhost | Label: ansible-fedora-37-1vcpu 2025-09-28 00:12:19.375740 | localhost | Product Name: OpenStack Nova 2025-09-28 00:12:19.375762 | localhost | Interface IP: 38.129.16.38 2025-09-28 00:12:19.391406 | 2025-09-28 00:12:19.391506 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-28 00:12:19.762727 | localhost -> localhost | changed 2025-09-28 00:12:19.768581 | 2025-09-28 00:12:19.768716 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-28 00:12:20.598402 | localhost -> localhost | changed 2025-09-28 00:12:20.644632 | 2025-09-28 00:12:20.644785 | PLAY [all:!appliance*] 2025-09-28 00:12:20.670656 | 2025-09-28 00:12:20.670819 | TASK [include_role : start-zuul-console] 2025-09-28 00:12:20.694024 | controller | ok 2025-09-28 00:12:20.715294 | 2025-09-28 00:12:20.715431 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-28 00:12:21.874900 | controller | ok 2025-09-28 00:12:21.894515 | 2025-09-28 00:12:21.894726 | TASK [use-our-mirror : Retrieve the IP address] 2025-09-28 00:12:24.366951 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-09-28 00:12:24.383743 | 2025-09-28 00:12:24.383967 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-09-28 00:12:24.767600 | controller | skipping: Conditional result was False 2025-09-28 00:12:24.777668 | 2025-09-28 00:12:24.777864 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-09-28 00:12:24.803162 | controller | skipping: Conditional result was False 2025-09-28 00:12:24.810436 | 2025-09-28 00:12:24.810542 | TASK [use-our-mirror : Create the podman configuration directory] 2025-09-28 00:12:24.826946 | controller | skipping: Conditional result was False 2025-09-28 00:12:24.835885 | 2025-09-28 00:12:24.836014 | TASK [use-our-mirror : Copy the podman configuration] 2025-09-28 00:12:24.860895 | controller | skipping: Conditional result was False 2025-09-28 00:12:24.868463 | 2025-09-28 00:12:24.868567 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-09-28 00:12:24.883850 | controller | skipping: Conditional result was False 2025-09-28 00:12:24.891288 | 2025-09-28 00:12:24.891433 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-09-28 00:12:24.907704 | controller | skipping: Conditional result was False 2025-09-28 00:12:24.919658 | 2025-09-28 00:12:24.919774 | TASK [Disable Fedora Modular] 2025-09-28 00:12:26.120048 | controller | changed 2025-09-28 00:12:26.132812 | 2025-09-28 00:12:26.132951 | TASK [Enable EPEL] 2025-09-28 00:12:26.160602 | controller | skipping: Conditional result was False 2025-09-28 00:12:26.174968 | 2025-09-28 00:12:26.175137 | TASK [Register the RHEL node] 2025-09-28 00:12:26.596640 | 2025-09-28 00:12:26.596949 | TASK [Show the subscription-manager status] 2025-09-28 00:12:26.977790 | controller | skipping: Conditional result was False 2025-09-28 00:12:26.993280 | 2025-09-28 00:12:26.993487 | TASK [Enable EPEL on RHEL] 2025-09-28 00:12:27.376351 | controller | skipping: Conditional result was False 2025-09-28 00:12:27.393241 | 2025-09-28 00:12:27.393479 | TASK [Install git and tox] 2025-09-28 00:14:54.892174 | controller | changed 2025-09-28 00:14:54.907393 | 2025-09-28 00:14:54.907533 | TASK [include_role : prepare-workspace] 2025-09-28 00:14:54.949283 | controller | ok 2025-09-28 00:14:54.987983 | 2025-09-28 00:14:54.988222 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-28 00:14:55.853909 | controller | ok 2025-09-28 00:14:55.865142 | 2025-09-28 00:14:55.865291 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-28 00:15:11.609273 | controller | Output suppressed because no_log was given 2025-09-28 00:15:11.624067 | 2025-09-28 00:15:11.624219 | TASK [include_role : prepare-workspace-openshift] 2025-09-28 00:15:11.642427 | controller | skipping: Conditional result was False 2025-09-28 00:15:11.700599 | 2025-09-28 00:15:11.700673 | PLAY [all:!appliance] 2025-09-28 00:15:11.716478 | 2025-09-28 00:15:11.716553 | TASK [Run add-build-sshkey role (RSA)] 2025-09-28 00:15:11.735815 | controller | ok 2025-09-28 00:15:11.751812 | 2025-09-28 00:15:11.751900 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-28 00:15:12.010070 | controller -> localhost | ok 2025-09-28 00:15:12.023848 | 2025-09-28 00:15:12.024012 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-28 00:15:12.063519 | controller | ok 2025-09-28 00:15:12.106268 | controller | included: /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-28 00:15:12.116601 | 2025-09-28 00:15:12.116762 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-28 00:15:12.620860 | controller -> localhost | Generating public/private rsa key pair. 2025-09-28 00:15:12.621051 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/work/da53e2e30aab42e3aaddcee46fd0cf71_id_rsa. 2025-09-28 00:15:12.621080 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/work/da53e2e30aab42e3aaddcee46fd0cf71_id_rsa.pub. 2025-09-28 00:15:12.621101 | controller -> localhost | The key fingerprint is: 2025-09-28 00:15:12.621121 | controller -> localhost | SHA256:w+3XDYD+sHP9qMSjre9JdPiPtJuN6AjOgigHD+K4T5Q zuul-build-sshkey 2025-09-28 00:15:12.621140 | controller -> localhost | The key's randomart image is: 2025-09-28 00:15:12.621159 | controller -> localhost | +---[RSA 2048]----+ 2025-09-28 00:15:12.621177 | controller -> localhost | | | 2025-09-28 00:15:12.621196 | controller -> localhost | | . | 2025-09-28 00:15:12.621214 | controller -> localhost | | . . | 2025-09-28 00:15:12.621231 | controller -> localhost | | . . o o | 2025-09-28 00:15:12.621249 | controller -> localhost | | E S + o o | 2025-09-28 00:15:12.621276 | controller -> localhost | |+. o * = o | 2025-09-28 00:15:12.621299 | controller -> localhost | |++.. . . + O = .| 2025-09-28 00:15:12.621319 | controller -> localhost | |oo+ . .o . X = X | 2025-09-28 00:15:12.621337 | controller -> localhost | |.=. .o +=O.B.+| 2025-09-28 00:15:12.621357 | controller -> localhost | +----[SHA256]-----+ 2025-09-28 00:15:12.621401 | controller -> localhost | ok: Runtime: 0:00:00.085095 2025-09-28 00:15:12.628186 | 2025-09-28 00:15:12.628250 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-28 00:15:12.650119 | controller | ok 2025-09-28 00:15:12.659877 | controller | included: /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-28 00:15:12.669311 | 2025-09-28 00:15:12.669409 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-28 00:15:12.694365 | controller | skipping: Conditional result was False 2025-09-28 00:15:12.702038 | 2025-09-28 00:15:12.702103 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-28 00:15:13.833501 | controller | changed 2025-09-28 00:15:13.842500 | 2025-09-28 00:15:13.842602 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-28 00:15:14.588744 | controller | ok 2025-09-28 00:15:14.601300 | 2025-09-28 00:15:14.601479 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-28 00:15:17.729929 | controller | changed 2025-09-28 00:15:17.741182 | 2025-09-28 00:15:17.741330 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-28 00:15:20.915506 | controller | changed 2025-09-28 00:15:20.930140 | 2025-09-28 00:15:20.930310 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-28 00:15:20.957855 | controller | skipping: Conditional result was False 2025-09-28 00:15:20.972734 | 2025-09-28 00:15:20.972927 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-28 00:15:21.390432 | controller -> localhost | changed 2025-09-28 00:15:21.404104 | 2025-09-28 00:15:21.404219 | TASK [add-build-sshkey : Add back temp key] 2025-09-28 00:15:21.734999 | controller -> localhost | Identity added: /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/work/da53e2e30aab42e3aaddcee46fd0cf71_id_rsa (zuul-build-sshkey) 2025-09-28 00:15:21.735334 | controller -> localhost | ok: Runtime: 0:00:00.013490 2025-09-28 00:15:21.749029 | 2025-09-28 00:15:21.749151 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-28 00:15:22.762546 | controller | ok 2025-09-28 00:15:22.768251 | 2025-09-28 00:15:22.768326 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-28 00:15:22.792583 | controller | skipping: Conditional result was False 2025-09-28 00:15:22.807020 | 2025-09-28 00:15:22.807122 | TASK [Run add-build-sshkey role (ECDSA)] 2025-09-28 00:15:22.829596 | controller | ok 2025-09-28 00:15:22.852267 | 2025-09-28 00:15:22.852395 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-28 00:15:23.084758 | controller -> localhost | ok 2025-09-28 00:15:23.101059 | 2025-09-28 00:15:23.101253 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-28 00:15:23.146364 | controller | ok 2025-09-28 00:15:23.166115 | controller | included: /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-28 00:15:23.174522 | 2025-09-28 00:15:23.174609 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-28 00:15:23.486228 | controller -> localhost | Generating public/private ecdsa key pair. 2025-09-28 00:15:23.486512 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/work/da53e2e30aab42e3aaddcee46fd0cf71_id_ecdsa. 2025-09-28 00:15:23.486569 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/work/da53e2e30aab42e3aaddcee46fd0cf71_id_ecdsa.pub. 2025-09-28 00:15:23.486626 | controller -> localhost | The key fingerprint is: 2025-09-28 00:15:23.486670 | controller -> localhost | SHA256:nms0vXK/15UqR4AKKH1gFgN9BBAeCtuGZCSTTUZnn6c zuul-build-sshkey 2025-09-28 00:15:23.486758 | controller -> localhost | The key's randomart image is: 2025-09-28 00:15:23.486801 | controller -> localhost | +---[ECDSA 521]---+ 2025-09-28 00:15:23.486840 | controller -> localhost | |=&O+*. | 2025-09-28 00:15:23.486878 | controller -> localhost | |O*oB.o . | 2025-09-28 00:15:23.486915 | controller -> localhost | |+.* + o . . | 2025-09-28 00:15:23.486953 | controller -> localhost | | o o o o . . | 2025-09-28 00:15:23.486990 | controller -> localhost | | . . E S. . .| 2025-09-28 00:15:23.487028 | controller -> localhost | | oo.. . ..| 2025-09-28 00:15:23.487065 | controller -> localhost | | .o. .. ...| 2025-09-28 00:15:23.487102 | controller -> localhost | | o.o. o. .| 2025-09-28 00:15:23.487139 | controller -> localhost | | ..o .=o | 2025-09-28 00:15:23.487177 | controller -> localhost | +----[SHA256]-----+ 2025-09-28 00:15:23.487257 | controller -> localhost | ok: Runtime: 0:00:00.014868 2025-09-28 00:15:23.501008 | 2025-09-28 00:15:23.501141 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-28 00:15:23.540070 | controller | ok 2025-09-28 00:15:23.558401 | controller | included: /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-28 00:15:23.571788 | 2025-09-28 00:15:23.571907 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-28 00:15:23.597370 | controller | skipping: Conditional result was False 2025-09-28 00:15:23.604306 | 2025-09-28 00:15:23.604376 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-28 00:15:24.576985 | controller | changed 2025-09-28 00:15:24.583599 | 2025-09-28 00:15:24.583666 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-28 00:15:25.313413 | controller | ok 2025-09-28 00:15:25.328560 | 2025-09-28 00:15:25.328799 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-28 00:15:28.465651 | controller | changed 2025-09-28 00:15:28.474460 | 2025-09-28 00:15:28.474559 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-28 00:15:31.546925 | controller | changed 2025-09-28 00:15:31.553160 | 2025-09-28 00:15:31.553249 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-28 00:15:31.567824 | controller | skipping: Conditional result was False 2025-09-28 00:15:31.576623 | 2025-09-28 00:15:31.576758 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-28 00:15:31.805773 | controller -> localhost | changed 2025-09-28 00:15:31.818219 | 2025-09-28 00:15:31.818327 | TASK [add-build-sshkey : Add back temp key] 2025-09-28 00:15:32.087461 | controller -> localhost | Identity added: /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/work/da53e2e30aab42e3aaddcee46fd0cf71_id_ecdsa (zuul-build-sshkey) 2025-09-28 00:15:32.087946 | controller -> localhost | ok: Runtime: 0:00:00.012569 2025-09-28 00:15:32.102248 | 2025-09-28 00:15:32.102390 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-28 00:15:32.833810 | controller | ok 2025-09-28 00:15:32.846063 | 2025-09-28 00:15:32.846212 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-28 00:15:32.871741 | controller | skipping: Conditional result was False 2025-09-28 00:15:32.910160 | 2025-09-28 00:15:32.910307 | TASK [include_role : remove-zuul-sshkey] 2025-09-28 00:15:32.938199 | controller | skipping: Conditional result was False 2025-09-28 00:15:32.946616 | 2025-09-28 00:15:32.946751 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-28 00:15:33.630807 | controller | ok: "logs" 2025-09-28 00:15:33.631247 | controller | ok: All items complete 2025-09-28 00:15:33.631308 | 2025-09-28 00:15:34.254913 | controller | ok: "artifacts" 2025-09-28 00:15:34.891969 | controller | ok: "docs" 2025-09-28 00:15:34.906991 | 2025-09-28 00:15:34.907236 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-28 00:15:35.661940 | controller | changed: "logs" 2025-09-28 00:15:36.320829 | controller | changed: "artifacts" 2025-09-28 00:15:36.968951 | controller | changed: "docs" 2025-09-28 00:15:37.028235 | 2025-09-28 00:15:37.028369 | PLAY RECAP 2025-09-28 00:15:37.028428 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-09-28 00:15:37.028463 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-28 00:15:37.028487 | 2025-09-28 00:15:37.162441 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-28 00:15:37.164374 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-28 00:15:37.794131 | 2025-09-28 00:15:37.794245 | PLAY [all] 2025-09-28 00:15:37.817543 | 2025-09-28 00:15:37.817647 | TASK [Install binary dependencies] 2025-09-28 00:15:37.887639 | controller | ok 2025-09-28 00:15:37.907284 | 2025-09-28 00:15:37.907390 | TASK [bindep : Include find tasks] 2025-09-28 00:15:37.938590 | controller | ok 2025-09-28 00:15:37.948356 | controller | included: /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-28 00:15:37.954750 | 2025-09-28 00:15:37.954819 | TASK [bindep : Look for bindep.txt] 2025-09-28 00:15:38.888258 | controller | ok 2025-09-28 00:15:38.901439 | 2025-09-28 00:15:38.901790 | TASK [bindep : Define bindep_file fact] 2025-09-28 00:15:38.929024 | controller | skipping: Conditional result was False 2025-09-28 00:15:38.942562 | 2025-09-28 00:15:38.942762 | TASK [bindep : Look for other-requirements.txt] 2025-09-28 00:15:39.583934 | controller | ok 2025-09-28 00:15:39.597631 | 2025-09-28 00:15:39.597904 | TASK [bindep : Define bindep_file fact] 2025-09-28 00:15:39.636329 | controller | skipping: Conditional result was False 2025-09-28 00:15:39.649483 | 2025-09-28 00:15:39.649633 | TASK [bindep : Look for bindep fallback file] 2025-09-28 00:15:39.686879 | controller | skipping: Conditional result was False 2025-09-28 00:15:39.697736 | 2025-09-28 00:15:39.697952 | TASK [bindep : Define bindep_file fact] 2025-09-28 00:15:39.734055 | controller | skipping: Conditional result was False 2025-09-28 00:15:39.744434 | 2025-09-28 00:15:39.744554 | TASK [bindep : Include bindep tasks] 2025-09-28 00:15:39.780295 | controller | skipping: Conditional result was False 2025-09-28 00:15:39.789548 | 2025-09-28 00:15:39.789666 | TASK [bindep : Include install tasks] 2025-09-28 00:15:39.815596 | controller | skipping: Conditional result was False 2025-09-28 00:15:39.824497 | 2025-09-28 00:15:39.824610 | LOOP [bindep : Include package tasks] 2025-09-28 00:15:39.896109 | 2025-09-28 00:15:39.896303 | TASK [Run test-setup role] 2025-09-28 00:15:39.918899 | controller | ok 2025-09-28 00:15:39.943627 | 2025-09-28 00:15:39.943802 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-28 00:15:40.586804 | controller | ok 2025-09-28 00:15:40.600121 | 2025-09-28 00:15:40.600282 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-28 00:15:40.973508 | controller | skipping: Conditional result was False 2025-09-28 00:15:41.031862 | 2025-09-28 00:15:41.031981 | PLAY RECAP 2025-09-28 00:15:41.032046 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-28 00:15:41.032113 | 2025-09-28 00:15:41.171144 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-28 00:15:41.172079 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-28 00:15:41.823734 | 2025-09-28 00:15:41.823862 | PLAY [controller] 2025-09-28 00:15:41.844086 | 2025-09-28 00:15:41.844263 | TASK [Create the /root directory] 2025-09-28 00:15:42.920970 | controller | ok 2025-09-28 00:15:42.931514 | 2025-09-28 00:15:42.931785 | TASK [Install glibc-langpack-en] 2025-09-28 00:15:51.650113 | controller | ok: Nothing to do 2025-09-28 00:15:51.658240 | 2025-09-28 00:15:51.658336 | TASK [Ensure controller directory exists] 2025-09-28 00:15:52.513082 | controller | changed 2025-09-28 00:15:52.526419 | 2025-09-28 00:15:52.526585 | TASK [Install container runtime] 2025-09-28 00:15:52.614845 | controller | ok 2025-09-28 00:15:52.673047 | 2025-09-28 00:15:52.673180 | LOOP [ensure-podman : Find distribution installation] 2025-09-28 00:15:52.715330 | controller | ok: "/var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-09-28 00:15:52.726846 | controller | included: /var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-09-28 00:15:52.737730 | 2025-09-28 00:15:52.737850 | TASK [ensure-podman : Install podman (RedHat)] 2025-09-28 00:18:01.285027 | controller | changed 2025-09-28 00:18:01.295846 | 2025-09-28 00:18:01.295954 | TASK [ensure-podman : Fetch podman version] 2025-09-28 00:18:02.512753 | controller | Client: Podman Engine 2025-09-28 00:18:02.555598 | controller | Version: 4.6.2 2025-09-28 00:18:02.555666 | controller | API Version: 4.6.2 2025-09-28 00:18:02.557822 | controller | Go Version: go1.19.12 2025-09-28 00:18:02.557854 | controller | Built: Mon Aug 28 19:38:31 2023 2025-09-28 00:18:02.557864 | controller | OS/Arch: linux/amd64 2025-09-28 00:18:03.170207 | controller | ok: Runtime: 0:00:00.345350 2025-09-28 00:18:03.183899 | 2025-09-28 00:18:03.184058 | TASK [ensure-podman : Print podman version installed] 2025-09-28 00:18:03.212281 | Podman version: Client: Podman Engine 2025-09-28 00:18:03.212527 | Version: 4.6.2 2025-09-28 00:18:03.212591 | API Version: 4.6.2 2025-09-28 00:18:03.212638 | Go Version: go1.19.12 2025-09-28 00:18:03.212710 | Built: Mon Aug 28 19:38:31 2023 2025-09-28 00:18:03.212764 | OS/Arch: linux/amd64 2025-09-28 00:18:03.225434 | 2025-09-28 00:18:03.225594 | TASK [ensure-podman : Validate podman engine] 2025-09-28 00:18:03.598046 | controller | skipping: Conditional result was False 2025-09-28 00:18:03.608350 | 2025-09-28 00:18:03.608490 | TASK [ensure-podman : Set up docker compatability socket] 2025-09-28 00:18:03.623231 | controller | skipping: Conditional result was False 2025-09-28 00:18:03.648989 | 2025-09-28 00:18:03.649179 | TASK [Ensure python3.8 is present] 2025-09-28 00:18:03.665575 | controller | skipping: Conditional result was False 2025-09-28 00:18:03.675283 | 2025-09-28 00:18:03.675425 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-09-28 00:18:03.699029 | controller | ok 2025-09-28 00:18:03.728182 | 2025-09-28 00:18:03.728325 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-09-28 00:18:07.509707 | controller | ok: Nothing to do 2025-09-28 00:18:07.525434 | 2025-09-28 00:18:07.525563 | TASK [our-ensure-python : Also install python3-devel] 2025-09-28 00:18:23.388069 | controller | changed 2025-09-28 00:18:23.399598 | 2025-09-28 00:18:23.399738 | TASK [Run ensure-virtualenv role] 2025-09-28 00:18:23.433537 | controller | ok 2025-09-28 00:18:23.505212 | 2025-09-28 00:18:23.505351 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-09-28 00:18:24.292812 | controller | /usr/bin/virtualenv 2025-09-28 00:18:24.862662 | controller | ok: Runtime: 0:00:00.004798 2025-09-28 00:18:24.871179 | 2025-09-28 00:18:24.871285 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-09-28 00:18:24.907656 | controller | skipping: Conditional result was False 2025-09-28 00:18:24.907929 | controller | ok: All items complete 2025-09-28 00:18:24.907958 | 2025-09-28 00:18:24.939070 | 2025-09-28 00:18:24.939243 | TASK [Find the full path of the Python interpreter] 2025-09-28 00:18:25.762645 | controller | /usr/bin/python3 2025-09-28 00:18:26.299487 | controller | ok 2025-09-28 00:18:26.308278 | 2025-09-28 00:18:26.308425 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-09-28 00:18:28.062413 | controller | created virtual environment CPython3.11.0.final.0-64 in 828ms 2025-09-28 00:18:28.126577 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-09-28 00:18:28.126632 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv) 2025-09-28 00:18:28.126646 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-09-28 00:18:28.126665 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-09-28 00:18:28.690584 | controller | changed 2025-09-28 00:18:28.700134 | 2025-09-28 00:18:28.700271 | TASK [Set selinux package] 2025-09-28 00:18:28.734055 | controller | ok 2025-09-28 00:18:28.742110 | 2025-09-28 00:18:28.742232 | TASK [Set selinux package (Fedora)] 2025-09-28 00:18:28.795078 | controller | ok 2025-09-28 00:18:28.803968 | 2025-09-28 00:18:28.804132 | TASK [Install selinux into virtualenv] 2025-09-28 00:18:32.199479 | controller | Collecting selinux-please-lie-to-me 2025-09-28 00:18:32.272079 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-09-28 00:18:32.918451 | controller | Collecting setuptools<50.0.0 2025-09-28 00:18:32.922965 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-09-28 00:18:32.979242 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 15.4 MB/s eta 0:00:00 2025-09-28 00:18:33.139135 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-09-28 00:18:33.139383 | controller | Attempting uninstall: setuptools 2025-09-28 00:18:33.143598 | controller | Found existing installation: setuptools 62.6.0 2025-09-28 00:18:33.262219 | controller | Uninstalling setuptools-62.6.0: 2025-09-28 00:18:33.275018 | controller | Successfully uninstalled setuptools-62.6.0 2025-09-28 00:18:34.212650 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-09-28 00:18:34.444946 | controller | 2025-09-28 00:18:34.797514 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-28 00:18:34.797565 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-28 00:18:35.222048 | controller | ok: Runtime: 0:00:05.199245 2025-09-28 00:18:35.228225 | 2025-09-28 00:18:35.228305 | TASK [Install pytest-forked into virtualenv] 2025-09-28 00:18:36.829832 | controller | Collecting pytest-forked 2025-09-28 00:18:36.916602 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-09-28 00:18:37.000257 | controller | Collecting py 2025-09-28 00:18:37.009429 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-09-28 00:18:37.053951 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.4 MB/s eta 0:00:00 2025-09-28 00:18:37.271034 | controller | Collecting pytest>=3.10 2025-09-28 00:18:37.275770 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-09-28 00:18:37.298701 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 17.7 MB/s eta 0:00:00 2025-09-28 00:18:37.370686 | controller | Collecting iniconfig>=1 2025-09-28 00:18:37.375030 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-09-28 00:18:37.461623 | controller | Collecting packaging>=20 2025-09-28 00:18:37.467991 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-09-28 00:18:37.483666 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.6 MB/s eta 0:00:00 2025-09-28 00:18:37.560757 | controller | Collecting pluggy<2,>=1.5 2025-09-28 00:18:37.573637 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-09-28 00:18:37.683028 | controller | Collecting pygments>=2.7.2 2025-09-28 00:18:37.690389 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-09-28 00:18:37.728266 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 37.9 MB/s eta 0:00:00 2025-09-28 00:18:37.876186 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-09-28 00:18:40.715315 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0 2025-09-28 00:18:40.733365 | controller | 2025-09-28 00:18:40.996742 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-28 00:18:40.996797 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-28 00:18:41.124930 | controller | ok: Runtime: 0:00:04.962370 2025-09-28 00:18:41.132717 | 2025-09-28 00:18:41.132844 | TASK [Update pip] 2025-09-28 00:18:42.561251 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-09-28 00:18:42.904555 | controller | Collecting pip 2025-09-28 00:18:42.979303 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-09-28 00:18:43.079564 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 19.6 MB/s eta 0:00:00 2025-09-28 00:18:43.210341 | controller | Installing collected packages: pip 2025-09-28 00:18:43.210558 | controller | Attempting uninstall: pip 2025-09-28 00:18:43.218549 | controller | Found existing installation: pip 22.2.2 2025-09-28 00:18:43.491292 | controller | Uninstalling pip-22.2.2: 2025-09-28 00:18:43.523256 | controller | Successfully uninstalled pip-22.2.2 2025-09-28 00:18:45.764255 | controller | Successfully installed pip-25.2 2025-09-28 00:18:46.518261 | controller | ok: Runtime: 0:00:04.123329 2025-09-28 00:18:46.532510 | 2025-09-28 00:18:46.532673 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-09-28 00:18:47.412226 | controller | changed 2025-09-28 00:18:47.479303 | 2025-09-28 00:18:47.479592 | TASK [Install ansible into virtualenv] 2025-09-28 00:18:48.813724 | controller | Processing ./src/github.com/ansible/ansible 2025-09-28 00:18:48.820312 | controller | Installing build dependencies: started 2025-09-28 00:18:51.036387 | controller | Installing build dependencies: finished with status 'done' 2025-09-28 00:18:51.037181 | controller | Getting requirements to build wheel: started 2025-09-28 00:18:52.701587 | controller | Getting requirements to build wheel: finished with status 'done' 2025-09-28 00:18:52.705401 | controller | Preparing metadata (pyproject.toml): started 2025-09-28 00:18:53.643571 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-09-28 00:18:53.648425 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-09-28 00:18:53.667289 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-09-28 00:18:54.379304 | controller | ERROR 2025-09-28 00:18:54.379564 | controller | { 2025-09-28 00:18:54.379604 | controller | "delta": "0:00:05.744807", 2025-09-28 00:18:54.379630 | controller | "end": "2025-09-28 00:18:53.875478", 2025-09-28 00:18:54.379650 | controller | "msg": "non-zero return code", 2025-09-28 00:18:54.379705 | controller | "rc": 1, 2025-09-28 00:18:54.379731 | controller | "start": "2025-09-28 00:18:48.130671" 2025-09-28 00:18:54.379748 | controller | } failure 2025-09-28 00:18:54.381439 | 2025-09-28 00:18:54.381492 | PLAY RECAP 2025-09-28 00:18:54.381537 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-09-28 00:18:54.381562 | 2025-09-28 00:18:54.492939 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-28 00:18:54.493918 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-28 00:18:55.058412 | 2025-09-28 00:18:55.058517 | PLAY [all] 2025-09-28 00:18:55.086195 | 2025-09-28 00:18:55.086325 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-28 00:18:56.929981 | controller | changed: non-zero return code 2025-09-28 00:18:56.944611 | 2025-09-28 00:18:56.944860 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-28 00:18:56.971937 | controller | skipping: Conditional result was False 2025-09-28 00:18:56.985168 | 2025-09-28 00:18:56.985323 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-28 00:18:57.025533 | 2025-09-28 00:18:57.025838 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-28 00:18:57.065983 | 2025-09-28 00:18:57.066253 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-28 00:18:57.093002 | controller | skipping: Conditional result was False 2025-09-28 00:18:57.106925 | 2025-09-28 00:18:57.107101 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-28 00:18:57.147611 | 2025-09-28 00:18:57.147936 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-28 00:18:57.174299 | controller | skipping: Conditional result was False 2025-09-28 00:18:57.187407 | 2025-09-28 00:18:57.187549 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-28 00:18:57.213504 | controller | skipping: Conditional result was False 2025-09-28 00:18:57.226385 | 2025-09-28 00:18:57.226526 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-28 00:18:57.252376 | controller | skipping: Conditional result was False 2025-09-28 00:18:57.299867 | 2025-09-28 00:18:57.299967 | PLAY RECAP 2025-09-28 00:18:57.300033 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-28 00:18:57.300068 | 2025-09-28 00:18:57.391147 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-28 00:18:57.391977 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-09-28 00:18:58.010600 | 2025-09-28 00:18:58.010770 | PLAY [all:!appliance*] 2025-09-28 00:18:58.040261 | 2025-09-28 00:18:58.040423 | TASK [unregister the node] 2025-09-28 00:18:58.397340 | controller | skipping: Conditional result was False 2025-09-28 00:18:58.403428 | 2025-09-28 00:18:58.403523 | TASK [include_role : fetch-output] 2025-09-28 00:18:58.454272 | controller | ok 2025-09-28 00:18:58.474816 | 2025-09-28 00:18:58.474912 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-28 00:18:58.561535 | controller | skipping: Conditional result was False 2025-09-28 00:18:58.568083 | 2025-09-28 00:18:58.568157 | TASK [fetch-output : Set log path for single node] 2025-09-28 00:18:58.608907 | controller | ok 2025-09-28 00:18:58.614438 | 2025-09-28 00:18:58.614507 | LOOP [fetch-output : Ensure local output dirs] 2025-09-28 00:18:59.021209 | controller -> localhost | ok: "/var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/work/logs" 2025-09-28 00:18:59.245811 | controller -> localhost | changed: "/var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/work/artifacts" 2025-09-28 00:18:59.491815 | controller -> localhost | changed: "/var/lib/zuul/builds/da53e2e30aab42e3aaddcee46fd0cf71/work/docs" 2025-09-28 00:18:59.509013 | 2025-09-28 00:18:59.509139 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-28 00:19:01.772519 | controller | changed: 2025-09-28 00:19:01.772824 | controller | .d..t...... ./ 2025-09-28 00:19:01.772871 | controller | cd+++++++++ controller/ 2025-09-28 00:19:01.772925 | controller | changed: All items complete 2025-09-28 00:19:01.772961 | 2025-09-28 00:19:03.892380 | controller | changed: .d..t...... ./ 2025-09-28 00:19:05.971841 | controller | changed: .d..t...... ./ 2025-09-28 00:19:06.007456 | 2025-09-28 00:19:06.007751 | TASK [include_role : fetch-output-openshift] 2025-09-28 00:19:06.035082 | controller | skipping: Conditional result was False 2025-09-28 00:19:06.050643 | 2025-09-28 00:19:06.050888 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-28 00:19:06.099755 | controller | skipping: Conditional result was False 2025-09-28 00:19:06.111769 | controller | skipping: Conditional result was False 2025-09-28 00:19:06.158143 | 2025-09-28 00:19:06.158262 | PLAY [localhost] 2025-09-28 00:19:06.176982 | 2025-09-28 00:19:06.177154 | TASK [Run Zuul manifest role] 2025-09-28 00:19:06.196209 | localhost | ok 2025-09-28 00:19:06.209827 | 2025-09-28 00:19:06.209928 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-28 00:19:06.592087 | localhost | changed 2025-09-28 00:19:06.603529 | 2025-09-28 00:19:06.603747 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-28 00:19:06.644106 | localhost | ok 2025-09-28 00:19:06.663834 | 2025-09-28 00:19:06.663998 | TASK [Set zuul-log-path fact] 2025-09-28 00:19:06.691360 | localhost | ok 2025-09-28 00:19:06.760823 | 2025-09-28 00:19:06.761003 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-28 00:19:06.802856 | localhost | ok 2025-09-28 00:19:06.811444 | 2025-09-28 00:19:06.811518 | LOOP [Run upload-logs-swift role] 2025-09-28 00:19:06.848696 | localhost | Output suppressed because no_log was given 2025-09-28 00:19:06.876921 | 2025-09-28 00:19:06.877062 | TASK [Set zuul-log-path fact] 2025-09-28 00:19:06.901742 | localhost | skipping: Conditional result was False 2025-09-28 00:19:06.909139 | 2025-09-28 00:19:06.909215 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-09-28 00:19:07.322497 | localhost -> localhost | ok: Runtime: 0:00:00.008922 2025-09-28 00:19:07.335314 | 2025-09-28 00:19:07.335456 | TASK [upload-logs-swift : Upload logs to swift]