2025-10-08 00:18:59.688610 | Job console starting... 2025-10-08 00:18:59.699401 | Updating repositories 2025-10-08 00:18:59.881837 | Preparing job workspace 2025-10-08 00:19:03.816660 | Running Ansible setup... 2025-10-08 00:19:12.170045 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-08 00:19:12.818665 | 2025-10-08 00:19:12.818813 | PLAY [localhost] 2025-10-08 00:19:12.828949 | 2025-10-08 00:19:12.829069 | TASK [Gathering Facts] 2025-10-08 00:19:13.946750 | localhost | ok 2025-10-08 00:19:13.976427 | 2025-10-08 00:19:13.976599 | TASK [Setup log path fact] 2025-10-08 00:19:14.007492 | localhost | ok 2025-10-08 00:19:14.024501 | 2025-10-08 00:19:14.024596 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-08 00:19:14.069405 | localhost | ok 2025-10-08 00:19:14.086671 | 2025-10-08 00:19:14.086873 | TASK [emit-job-header : Print job information] 2025-10-08 00:19:14.140442 | # Job Information 2025-10-08 00:19:14.140834 | Ansible Version: 2.15.12 2025-10-08 00:19:14.140914 | Job: ansible-test-sanity-docker-milestone 2025-10-08 00:19:14.140972 | Pipeline: periodic 2025-10-08 00:19:14.141017 | Executor: ze04.softwarefactory-project.io 2025-10-08 00:19:14.141060 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-08 00:19:14.141109 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/4ad/ansible/4ad1ba75b9b648c39f87b644968bd056/ 2025-10-08 00:19:14.141154 | Event ID: dfad45c092da40fea8db4cca31b37c4e 2025-10-08 00:19:14.151257 | 2025-10-08 00:19:14.151413 | LOOP [emit-job-header : Print node information] 2025-10-08 00:19:14.259479 | localhost | ok: 2025-10-08 00:19:14.259662 | localhost | # Node Information 2025-10-08 00:19:14.259707 | localhost | Inventory Hostname: controller 2025-10-08 00:19:14.259729 | localhost | Hostname: np0005475139 2025-10-08 00:19:14.259749 | localhost | Username: zuul 2025-10-08 00:19:14.259772 | localhost | Distro: Fedora 37 2025-10-08 00:19:14.259790 | localhost | Provider: ansible-vexxhost-ams1 2025-10-08 00:19:14.259820 | localhost | Region: ams1 2025-10-08 00:19:14.259843 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-08 00:19:14.259866 | localhost | Product Name: OpenStack Nova 2025-10-08 00:19:14.259888 | localhost | Interface IP: 38.129.16.104 2025-10-08 00:19:14.279811 | 2025-10-08 00:19:14.279999 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-08 00:19:14.674994 | localhost -> localhost | changed 2025-10-08 00:19:14.686596 | 2025-10-08 00:19:14.686799 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-08 00:19:15.633739 | localhost -> localhost | changed 2025-10-08 00:19:15.655337 | 2025-10-08 00:19:15.655445 | PLAY [all:!appliance*] 2025-10-08 00:19:15.677390 | 2025-10-08 00:19:15.677524 | TASK [include_role : start-zuul-console] 2025-10-08 00:19:15.697721 | controller | ok 2025-10-08 00:19:15.712475 | 2025-10-08 00:19:15.712604 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-08 00:19:16.757535 | controller | ok 2025-10-08 00:19:16.781970 | 2025-10-08 00:19:16.782111 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-08 00:19:19.301214 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-08 00:19:19.322823 | 2025-10-08 00:19:19.323043 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-08 00:19:19.702101 | controller | skipping: Conditional result was False 2025-10-08 00:19:19.716822 | 2025-10-08 00:19:19.716998 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-08 00:19:19.754961 | controller | skipping: Conditional result was False 2025-10-08 00:19:19.771223 | 2025-10-08 00:19:19.771416 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-08 00:19:19.801973 | controller | skipping: Conditional result was False 2025-10-08 00:19:19.818768 | 2025-10-08 00:19:19.818949 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-08 00:19:19.848887 | controller | skipping: Conditional result was False 2025-10-08 00:19:19.866062 | 2025-10-08 00:19:19.866220 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-08 00:19:19.894296 | controller | skipping: Conditional result was False 2025-10-08 00:19:19.904757 | 2025-10-08 00:19:19.904862 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-08 00:19:19.931778 | controller | skipping: Conditional result was False 2025-10-08 00:19:19.950633 | 2025-10-08 00:19:19.950797 | TASK [Disable Fedora Modular] 2025-10-08 00:19:21.076049 | controller | changed 2025-10-08 00:19:21.091243 | 2025-10-08 00:19:21.091377 | TASK [Enable EPEL] 2025-10-08 00:19:21.119015 | controller | skipping: Conditional result was False 2025-10-08 00:19:21.132169 | 2025-10-08 00:19:21.132433 | TASK [Register the RHEL node] 2025-10-08 00:19:21.565881 | 2025-10-08 00:19:21.566178 | TASK [Show the subscription-manager status] 2025-10-08 00:19:21.964226 | controller | skipping: Conditional result was False 2025-10-08 00:19:21.978788 | 2025-10-08 00:19:21.978927 | TASK [Enable EPEL on RHEL] 2025-10-08 00:19:22.369085 | controller | skipping: Conditional result was False 2025-10-08 00:19:22.383577 | 2025-10-08 00:19:22.383763 | TASK [Install git and tox] 2025-10-08 00:21:55.320549 | controller | changed 2025-10-08 00:21:55.338489 | 2025-10-08 00:21:55.338947 | TASK [include_role : prepare-workspace] 2025-10-08 00:21:55.385421 | controller | ok 2025-10-08 00:21:55.425655 | 2025-10-08 00:21:55.425842 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-08 00:21:56.327283 | controller | ok 2025-10-08 00:21:56.339718 | 2025-10-08 00:21:56.339835 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-08 00:22:12.059929 | controller | Output suppressed because no_log was given 2025-10-08 00:22:12.072248 | 2025-10-08 00:22:12.072314 | TASK [include_role : prepare-workspace-openshift] 2025-10-08 00:22:12.096564 | controller | skipping: Conditional result was False 2025-10-08 00:22:12.125463 | 2025-10-08 00:22:12.125519 | PLAY [all:!appliance] 2025-10-08 00:22:12.141537 | 2025-10-08 00:22:12.141599 | TASK [Run add-build-sshkey role (RSA)] 2025-10-08 00:22:12.181436 | controller | ok 2025-10-08 00:22:12.196016 | 2025-10-08 00:22:12.196103 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-08 00:22:12.467462 | controller -> localhost | ok 2025-10-08 00:22:12.474211 | 2025-10-08 00:22:12.474347 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-08 00:22:12.511437 | controller | ok 2025-10-08 00:22:12.525874 | controller | included: /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-08 00:22:12.532063 | 2025-10-08 00:22:12.532139 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-08 00:22:12.994123 | controller -> localhost | Generating public/private rsa key pair. 2025-10-08 00:22:12.994328 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/work/4ad1ba75b9b648c39f87b644968bd056_id_rsa. 2025-10-08 00:22:12.994357 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/work/4ad1ba75b9b648c39f87b644968bd056_id_rsa.pub. 2025-10-08 00:22:12.994378 | controller -> localhost | The key fingerprint is: 2025-10-08 00:22:12.994397 | controller -> localhost | SHA256:NnCMyjUbLc/jPwFaTdauPVwQmdlXZRfiEr8RV+1x8uw zuul-build-sshkey 2025-10-08 00:22:12.994416 | controller -> localhost | The key's randomart image is: 2025-10-08 00:22:12.994434 | controller -> localhost | +---[RSA 2048]----+ 2025-10-08 00:22:12.994452 | controller -> localhost | | o.O o%| 2025-10-08 00:22:12.994470 | controller -> localhost | | + o X *o=| 2025-10-08 00:22:12.994487 | controller -> localhost | | B ++ o = *o| 2025-10-08 00:22:12.994504 | controller -> localhost | | . o Xo . o + +| 2025-10-08 00:22:12.994522 | controller -> localhost | | o .oS. + o . | 2025-10-08 00:22:12.994547 | controller -> localhost | | .o oo + E| 2025-10-08 00:22:12.994568 | controller -> localhost | | . . . | 2025-10-08 00:22:12.994587 | controller -> localhost | | .. | 2025-10-08 00:22:12.994607 | controller -> localhost | | .. | 2025-10-08 00:22:12.994630 | controller -> localhost | +----[SHA256]-----+ 2025-10-08 00:22:12.994709 | controller -> localhost | ok: Runtime: 0:00:00.121838 2025-10-08 00:22:13.001953 | 2025-10-08 00:22:13.002036 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-08 00:22:13.038853 | controller | ok 2025-10-08 00:22:13.049572 | controller | included: /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-08 00:22:13.059303 | 2025-10-08 00:22:13.059402 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-08 00:22:13.084033 | controller | skipping: Conditional result was False 2025-10-08 00:22:13.090315 | 2025-10-08 00:22:13.090391 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-08 00:22:14.217503 | controller | changed 2025-10-08 00:22:14.225828 | 2025-10-08 00:22:14.225949 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-08 00:22:14.894896 | controller | ok 2025-10-08 00:22:14.906208 | 2025-10-08 00:22:14.906314 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-08 00:22:17.938375 | controller | changed 2025-10-08 00:22:17.944338 | 2025-10-08 00:22:17.944406 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-08 00:22:21.033082 | controller | changed 2025-10-08 00:22:21.055192 | 2025-10-08 00:22:21.055338 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-08 00:22:21.080600 | controller | skipping: Conditional result was False 2025-10-08 00:22:21.087564 | 2025-10-08 00:22:21.087712 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-08 00:22:21.450877 | controller -> localhost | changed 2025-10-08 00:22:21.467563 | 2025-10-08 00:22:21.467770 | TASK [add-build-sshkey : Add back temp key] 2025-10-08 00:22:21.781663 | controller -> localhost | Identity added: /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/work/4ad1ba75b9b648c39f87b644968bd056_id_rsa (zuul-build-sshkey) 2025-10-08 00:22:21.781886 | controller -> localhost | ok: Runtime: 0:00:00.010134 2025-10-08 00:22:21.789621 | 2025-10-08 00:22:21.789754 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-08 00:22:22.779793 | controller | ok 2025-10-08 00:22:22.787216 | 2025-10-08 00:22:22.787301 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-08 00:22:22.822407 | controller | skipping: Conditional result was False 2025-10-08 00:22:22.838938 | 2025-10-08 00:22:22.839031 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-08 00:22:22.876505 | controller | ok 2025-10-08 00:22:22.903077 | 2025-10-08 00:22:22.903186 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-08 00:22:23.193151 | controller -> localhost | ok 2025-10-08 00:22:23.200117 | 2025-10-08 00:22:23.200181 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-08 00:22:23.240440 | controller | ok 2025-10-08 00:22:23.258945 | controller | included: /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-08 00:22:23.267870 | 2025-10-08 00:22:23.267993 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-08 00:22:23.559824 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-08 00:22:23.560095 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/work/4ad1ba75b9b648c39f87b644968bd056_id_ecdsa. 2025-10-08 00:22:23.560128 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/work/4ad1ba75b9b648c39f87b644968bd056_id_ecdsa.pub. 2025-10-08 00:22:23.560159 | controller -> localhost | The key fingerprint is: 2025-10-08 00:22:23.560180 | controller -> localhost | SHA256:xj3fZDxlxq4nEi/z0SrCJD10iVM8QW4uXlokvI7e1Us zuul-build-sshkey 2025-10-08 00:22:23.560199 | controller -> localhost | The key's randomart image is: 2025-10-08 00:22:23.560218 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-08 00:22:23.560236 | controller -> localhost | | oo. | 2025-10-08 00:22:23.560254 | controller -> localhost | | . .+ . | 2025-10-08 00:22:23.560271 | controller -> localhost | | oo+o =| 2025-10-08 00:22:23.560289 | controller -> localhost | | . .+*o. = | 2025-10-08 00:22:23.560306 | controller -> localhost | | So=o= = .| 2025-10-08 00:22:23.560323 | controller -> localhost | | ..++B B + | 2025-10-08 00:22:23.560340 | controller -> localhost | | .++.* E o| 2025-10-08 00:22:23.560357 | controller -> localhost | | . .o..* * | 2025-10-08 00:22:23.560374 | controller -> localhost | | . .. .+ | 2025-10-08 00:22:23.560391 | controller -> localhost | +----[SHA256]-----+ 2025-10-08 00:22:23.560444 | controller -> localhost | ok: Runtime: 0:00:00.014922 2025-10-08 00:22:23.567476 | 2025-10-08 00:22:23.567560 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-08 00:22:23.588497 | controller | ok 2025-10-08 00:22:23.596865 | controller | included: /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-08 00:22:23.606108 | 2025-10-08 00:22:23.606255 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-08 00:22:23.630857 | controller | skipping: Conditional result was False 2025-10-08 00:22:23.637199 | 2025-10-08 00:22:23.637261 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-08 00:22:24.558059 | controller | changed 2025-10-08 00:22:24.570217 | 2025-10-08 00:22:24.570349 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-08 00:22:25.303425 | controller | ok 2025-10-08 00:22:25.316863 | 2025-10-08 00:22:25.317042 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-08 00:22:28.425554 | controller | changed 2025-10-08 00:22:28.431561 | 2025-10-08 00:22:28.431641 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-08 00:22:31.576022 | controller | changed 2025-10-08 00:22:31.589344 | 2025-10-08 00:22:31.589489 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-08 00:22:31.616242 | controller | skipping: Conditional result was False 2025-10-08 00:22:31.627238 | 2025-10-08 00:22:31.627362 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-08 00:22:31.870095 | controller -> localhost | changed 2025-10-08 00:22:31.882256 | 2025-10-08 00:22:31.882342 | TASK [add-build-sshkey : Add back temp key] 2025-10-08 00:22:32.194222 | controller -> localhost | Identity added: /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/work/4ad1ba75b9b648c39f87b644968bd056_id_ecdsa (zuul-build-sshkey) 2025-10-08 00:22:32.194532 | controller -> localhost | ok: Runtime: 0:00:00.015399 2025-10-08 00:22:32.202381 | 2025-10-08 00:22:32.202494 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-08 00:22:32.928483 | controller | ok 2025-10-08 00:22:32.938383 | 2025-10-08 00:22:32.938485 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-08 00:22:32.974733 | controller | skipping: Conditional result was False 2025-10-08 00:22:32.996158 | 2025-10-08 00:22:32.996385 | TASK [include_role : remove-zuul-sshkey] 2025-10-08 00:22:33.014012 | controller | skipping: Conditional result was False 2025-10-08 00:22:33.024511 | 2025-10-08 00:22:33.024646 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-08 00:22:33.745613 | controller | ok: "logs" 2025-10-08 00:22:33.746092 | controller | ok: All items complete 2025-10-08 00:22:33.746156 | 2025-10-08 00:22:34.419409 | controller | ok: "artifacts" 2025-10-08 00:22:35.122520 | controller | ok: "docs" 2025-10-08 00:22:35.149628 | 2025-10-08 00:22:35.149943 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-08 00:22:35.958789 | controller | changed: "logs" 2025-10-08 00:22:36.619639 | controller | changed: "artifacts" 2025-10-08 00:22:37.421474 | controller | changed: "docs" 2025-10-08 00:22:37.453184 | 2025-10-08 00:22:37.453326 | PLAY RECAP 2025-10-08 00:22:37.453391 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-08 00:22:37.453427 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-08 00:22:37.453452 | 2025-10-08 00:22:37.590478 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-08 00:22:37.591405 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-08 00:22:38.218428 | 2025-10-08 00:22:38.218536 | PLAY [all] 2025-10-08 00:22:38.241474 | 2025-10-08 00:22:38.241570 | TASK [Install binary dependencies] 2025-10-08 00:22:38.293334 | controller | ok 2025-10-08 00:22:38.313579 | 2025-10-08 00:22:38.313691 | TASK [bindep : Include find tasks] 2025-10-08 00:22:38.354086 | controller | ok 2025-10-08 00:22:38.362028 | controller | included: /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-08 00:22:38.368770 | 2025-10-08 00:22:38.368844 | TASK [bindep : Look for bindep.txt] 2025-10-08 00:22:39.392138 | controller | ok 2025-10-08 00:22:39.408805 | 2025-10-08 00:22:39.408978 | TASK [bindep : Define bindep_file fact] 2025-10-08 00:22:39.426597 | controller | skipping: Conditional result was False 2025-10-08 00:22:39.441508 | 2025-10-08 00:22:39.441661 | TASK [bindep : Look for other-requirements.txt] 2025-10-08 00:22:40.117896 | controller | ok 2025-10-08 00:22:40.137673 | 2025-10-08 00:22:40.137986 | TASK [bindep : Define bindep_file fact] 2025-10-08 00:22:40.165162 | controller | skipping: Conditional result was False 2025-10-08 00:22:40.175808 | 2025-10-08 00:22:40.175968 | TASK [bindep : Look for bindep fallback file] 2025-10-08 00:22:40.213247 | controller | skipping: Conditional result was False 2025-10-08 00:22:40.221900 | 2025-10-08 00:22:40.222014 | TASK [bindep : Define bindep_file fact] 2025-10-08 00:22:40.247831 | controller | skipping: Conditional result was False 2025-10-08 00:22:40.254354 | 2025-10-08 00:22:40.254433 | TASK [bindep : Include bindep tasks] 2025-10-08 00:22:40.287225 | controller | skipping: Conditional result was False 2025-10-08 00:22:40.294708 | 2025-10-08 00:22:40.294805 | TASK [bindep : Include install tasks] 2025-10-08 00:22:40.326695 | controller | skipping: Conditional result was False 2025-10-08 00:22:40.333637 | 2025-10-08 00:22:40.334173 | LOOP [bindep : Include package tasks] 2025-10-08 00:22:40.394590 | 2025-10-08 00:22:40.396980 | TASK [Run test-setup role] 2025-10-08 00:22:40.422316 | controller | ok 2025-10-08 00:22:40.441616 | 2025-10-08 00:22:40.441828 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-08 00:22:41.104151 | controller | ok 2025-10-08 00:22:41.119422 | 2025-10-08 00:22:41.119580 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-08 00:22:41.495096 | controller | skipping: Conditional result was False 2025-10-08 00:22:41.552831 | 2025-10-08 00:22:41.553037 | PLAY RECAP 2025-10-08 00:22:41.553099 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-08 00:22:41.553127 | 2025-10-08 00:22:41.708226 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-08 00:22:41.710324 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-08 00:22:42.349846 | 2025-10-08 00:22:42.350002 | PLAY [controller] 2025-10-08 00:22:42.372127 | 2025-10-08 00:22:42.372256 | TASK [Create the /root directory] 2025-10-08 00:22:43.473521 | controller | ok 2025-10-08 00:22:43.490982 | 2025-10-08 00:22:43.491283 | TASK [Install glibc-langpack-en] 2025-10-08 00:22:52.508034 | controller | ok: Nothing to do 2025-10-08 00:22:52.521565 | 2025-10-08 00:22:52.521751 | TASK [Ensure controller directory exists] 2025-10-08 00:22:53.374695 | controller | changed 2025-10-08 00:22:53.380490 | 2025-10-08 00:22:53.380555 | TASK [Install container runtime] 2025-10-08 00:22:53.444334 | controller | ok 2025-10-08 00:22:53.488221 | 2025-10-08 00:22:53.488338 | LOOP [ensure-podman : Find distribution installation] 2025-10-08 00:22:53.516896 | controller | ok: "/var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-08 00:22:53.531009 | controller | included: /var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-08 00:22:53.538729 | 2025-10-08 00:22:53.538862 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-08 00:25:03.815757 | controller | changed 2025-10-08 00:25:03.829542 | 2025-10-08 00:25:03.829687 | TASK [ensure-podman : Fetch podman version] 2025-10-08 00:25:05.103386 | controller | Client: Podman Engine 2025-10-08 00:25:05.142587 | controller | Version: 4.6.2 2025-10-08 00:25:05.142662 | controller | API Version: 4.6.2 2025-10-08 00:25:05.142740 | controller | Go Version: go1.19.12 2025-10-08 00:25:05.142762 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-08 00:25:05.142770 | controller | OS/Arch: linux/amd64 2025-10-08 00:25:05.707265 | controller | ok: Runtime: 0:00:00.345073 2025-10-08 00:25:05.722873 | 2025-10-08 00:25:05.723044 | TASK [ensure-podman : Print podman version installed] 2025-10-08 00:25:05.764689 | Podman version: Client: Podman Engine 2025-10-08 00:25:05.765017 | Version: 4.6.2 2025-10-08 00:25:05.765102 | API Version: 4.6.2 2025-10-08 00:25:05.765159 | Go Version: go1.19.12 2025-10-08 00:25:05.765203 | Built: Mon Aug 28 19:38:31 2023 2025-10-08 00:25:05.765252 | OS/Arch: linux/amd64 2025-10-08 00:25:05.777884 | 2025-10-08 00:25:05.778021 | TASK [ensure-podman : Validate podman engine] 2025-10-08 00:25:06.141203 | controller | skipping: Conditional result was False 2025-10-08 00:25:06.155098 | 2025-10-08 00:25:06.155288 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-08 00:25:06.171831 | controller | skipping: Conditional result was False 2025-10-08 00:25:06.198811 | 2025-10-08 00:25:06.198992 | TASK [Ensure python3.8 is present] 2025-10-08 00:25:06.225934 | controller | skipping: Conditional result was False 2025-10-08 00:25:06.240449 | 2025-10-08 00:25:06.240609 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-08 00:25:06.271647 | controller | ok 2025-10-08 00:25:06.308271 | 2025-10-08 00:25:06.308428 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-08 00:25:10.420631 | controller | ok: Nothing to do 2025-10-08 00:25:10.434867 | 2025-10-08 00:25:10.435026 | TASK [our-ensure-python : Also install python3-devel] 2025-10-08 00:25:26.252059 | controller | changed 2025-10-08 00:25:26.276510 | 2025-10-08 00:25:26.276657 | TASK [Run ensure-virtualenv role] 2025-10-08 00:25:26.308343 | controller | ok 2025-10-08 00:25:26.345533 | 2025-10-08 00:25:26.345637 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-08 00:25:27.145725 | controller | /usr/bin/virtualenv 2025-10-08 00:25:27.733083 | controller | ok: Runtime: 0:00:00.005681 2025-10-08 00:25:27.747669 | 2025-10-08 00:25:27.747897 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-08 00:25:27.771370 | controller | skipping: Conditional result was False 2025-10-08 00:25:27.771672 | controller | ok: All items complete 2025-10-08 00:25:27.771724 | 2025-10-08 00:25:27.803979 | 2025-10-08 00:25:27.804189 | TASK [Find the full path of the Python interpreter] 2025-10-08 00:25:28.608054 | controller | /usr/bin/python3 2025-10-08 00:25:29.179051 | controller | ok 2025-10-08 00:25:29.193572 | 2025-10-08 00:25:29.193797 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-08 00:25:31.150131 | controller | created virtual environment CPython3.11.0.final.0-64 in 945ms 2025-10-08 00:25:31.250641 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-08 00:25:31.250699 | 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-10-08 00:25:31.250712 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-08 00:25:31.250746 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-08 00:25:31.578456 | controller | changed 2025-10-08 00:25:31.589480 | 2025-10-08 00:25:31.589603 | TASK [Set selinux package] 2025-10-08 00:25:31.629031 | controller | ok 2025-10-08 00:25:31.637318 | 2025-10-08 00:25:31.637438 | TASK [Set selinux package (Fedora)] 2025-10-08 00:25:31.693532 | controller | ok 2025-10-08 00:25:31.701144 | 2025-10-08 00:25:31.701233 | TASK [Install selinux into virtualenv] 2025-10-08 00:25:35.322067 | controller | Collecting selinux-please-lie-to-me 2025-10-08 00:25:35.395009 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-08 00:25:36.020034 | controller | Collecting setuptools<50.0.0 2025-10-08 00:25:36.028147 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-08 00:25:36.089800 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 14.4 MB/s eta 0:00:00 2025-10-08 00:25:36.269364 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-08 00:25:36.270672 | controller | Attempting uninstall: setuptools 2025-10-08 00:25:36.274647 | controller | Found existing installation: setuptools 62.6.0 2025-10-08 00:25:36.379118 | controller | Uninstalling setuptools-62.6.0: 2025-10-08 00:25:36.394890 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-08 00:25:37.269266 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-08 00:25:37.518875 | controller | 2025-10-08 00:25:37.888280 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-08 00:25:37.888336 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-08 00:25:38.114168 | controller | ok: Runtime: 0:00:05.325917 2025-10-08 00:25:38.127108 | 2025-10-08 00:25:38.127241 | TASK [Install pytest-forked into virtualenv] 2025-10-08 00:25:39.843392 | controller | Collecting pytest-forked 2025-10-08 00:25:39.931987 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-08 00:25:40.000636 | controller | Collecting py 2025-10-08 00:25:40.007680 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-08 00:25:40.052458 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.4 MB/s eta 0:00:00 2025-10-08 00:25:40.274062 | controller | Collecting pytest>=3.10 2025-10-08 00:25:40.279391 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-08 00:25:40.312712 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 12.0 MB/s eta 0:00:00 2025-10-08 00:25:40.392218 | controller | Collecting iniconfig>=1 2025-10-08 00:25:40.400375 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-08 00:25:40.493091 | controller | Collecting packaging>=20 2025-10-08 00:25:40.501464 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-08 00:25:40.527321 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 3.9 MB/s eta 0:00:00 2025-10-08 00:25:40.593466 | controller | Collecting pluggy<2,>=1.5 2025-10-08 00:25:40.597911 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-08 00:25:40.714653 | controller | Collecting pygments>=2.7.2 2025-10-08 00:25:40.718849 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-08 00:25:40.751633 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 46.0 MB/s eta 0:00:00 2025-10-08 00:25:40.889458 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-08 00:25:43.474112 | 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-10-08 00:25:43.492232 | controller | 2025-10-08 00:25:43.762720 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-08 00:25:43.762777 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-08 00:25:44.014884 | controller | ok: Runtime: 0:00:04.815243 2025-10-08 00:25:44.020959 | 2025-10-08 00:25:44.021037 | TASK [Update pip] 2025-10-08 00:25:45.564027 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-08 00:25:45.878095 | controller | Collecting pip 2025-10-08 00:25:45.959148 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-08 00:25:46.052119 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 20.0 MB/s eta 0:00:00 2025-10-08 00:25:46.188758 | controller | Installing collected packages: pip 2025-10-08 00:25:46.189078 | controller | Attempting uninstall: pip 2025-10-08 00:25:46.194772 | controller | Found existing installation: pip 22.2.2 2025-10-08 00:25:46.492533 | controller | Uninstalling pip-22.2.2: 2025-10-08 00:25:46.523827 | controller | Successfully uninstalled pip-22.2.2 2025-10-08 00:25:48.432908 | controller | Successfully installed pip-25.2 2025-10-08 00:25:48.899475 | controller | ok: Runtime: 0:00:03.854397 2025-10-08 00:25:48.927207 | 2025-10-08 00:25:48.927361 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-08 00:25:49.857975 | controller | changed 2025-10-08 00:25:49.863576 | 2025-10-08 00:25:49.863640 | TASK [Install ansible into virtualenv] 2025-10-08 00:25:51.296153 | controller | Processing ./src/github.com/ansible/ansible 2025-10-08 00:25:51.301544 | controller | Installing build dependencies: started 2025-10-08 00:25:53.613613 | controller | Installing build dependencies: finished with status 'done' 2025-10-08 00:25:55.340131 | controller | Getting requirements to build wheel: started 2025-10-08 00:25:55.340219 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-08 00:25:56.387231 | controller | Preparing metadata (pyproject.toml): started 2025-10-08 00:25:56.387281 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-08 00:25:56.391034 | 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-10-08 00:25:56.396894 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-08 00:25:56.760254 | controller | ERROR 2025-10-08 00:25:56.760487 | controller | { 2025-10-08 00:25:56.760534 | controller | "delta": "0:00:06.015281", 2025-10-08 00:25:56.760559 | controller | "end": "2025-10-08 00:25:56.592866", 2025-10-08 00:25:56.760578 | controller | "msg": "non-zero return code", 2025-10-08 00:25:56.760604 | controller | "rc": 1, 2025-10-08 00:25:56.760621 | controller | "start": "2025-10-08 00:25:50.577585" 2025-10-08 00:25:56.760643 | controller | } failure 2025-10-08 00:25:56.762477 | 2025-10-08 00:25:56.762526 | PLAY RECAP 2025-10-08 00:25:56.762572 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-08 00:25:56.762593 | 2025-10-08 00:25:56.891858 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-08 00:25:56.893150 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-08 00:25:57.458915 | 2025-10-08 00:25:57.459038 | PLAY [all] 2025-10-08 00:25:57.480362 | 2025-10-08 00:25:57.480456 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-08 00:25:59.348155 | controller | changed: non-zero return code 2025-10-08 00:25:59.356918 | 2025-10-08 00:25:59.357071 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-08 00:25:59.372281 | controller | skipping: Conditional result was False 2025-10-08 00:25:59.385144 | 2025-10-08 00:25:59.385339 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-08 00:25:59.418640 | 2025-10-08 00:25:59.419026 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-08 00:25:59.463461 | 2025-10-08 00:25:59.463631 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-08 00:25:59.478239 | controller | skipping: Conditional result was False 2025-10-08 00:25:59.485411 | 2025-10-08 00:25:59.485500 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-08 00:25:59.519556 | 2025-10-08 00:25:59.519732 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-08 00:25:59.533006 | controller | skipping: Conditional result was False 2025-10-08 00:25:59.539751 | 2025-10-08 00:25:59.539833 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-08 00:25:59.553312 | controller | skipping: Conditional result was False 2025-10-08 00:25:59.560050 | 2025-10-08 00:25:59.560141 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-08 00:25:59.573483 | controller | skipping: Conditional result was False 2025-10-08 00:25:59.600041 | 2025-10-08 00:25:59.600136 | PLAY RECAP 2025-10-08 00:25:59.600181 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-08 00:25:59.600201 | 2025-10-08 00:25:59.706011 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-08 00:25:59.707173 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-08 00:26:00.277696 | 2025-10-08 00:26:00.277817 | PLAY [all:!appliance*] 2025-10-08 00:26:00.310617 | 2025-10-08 00:26:00.310748 | TASK [unregister the node] 2025-10-08 00:26:00.665599 | controller | skipping: Conditional result was False 2025-10-08 00:26:00.677884 | 2025-10-08 00:26:00.678044 | TASK [include_role : fetch-output] 2025-10-08 00:26:00.748006 | controller | ok 2025-10-08 00:26:00.787817 | 2025-10-08 00:26:00.787944 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-08 00:26:00.864333 | controller | skipping: Conditional result was False 2025-10-08 00:26:00.878286 | 2025-10-08 00:26:00.878441 | TASK [fetch-output : Set log path for single node] 2025-10-08 00:26:00.938400 | controller | ok 2025-10-08 00:26:00.952802 | 2025-10-08 00:26:00.952987 | LOOP [fetch-output : Ensure local output dirs] 2025-10-08 00:26:01.406098 | controller -> localhost | ok: "/var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/work/logs" 2025-10-08 00:26:01.700775 | controller -> localhost | changed: "/var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/work/artifacts" 2025-10-08 00:26:01.956540 | controller -> localhost | changed: "/var/lib/zuul/builds/4ad1ba75b9b648c39f87b644968bd056/work/docs" 2025-10-08 00:26:01.983008 | 2025-10-08 00:26:01.983189 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-08 00:26:04.241961 | controller | changed: 2025-10-08 00:26:04.242233 | controller | .d..t...... ./ 2025-10-08 00:26:04.242276 | controller | cd+++++++++ controller/ 2025-10-08 00:26:04.242327 | controller | changed: All items complete 2025-10-08 00:26:04.242355 | 2025-10-08 00:26:06.349537 | controller | changed: .d..t...... ./ 2025-10-08 00:26:08.460423 | controller | changed: .d..t...... ./ 2025-10-08 00:26:08.495748 | 2025-10-08 00:26:08.495986 | TASK [include_role : fetch-output-openshift] 2025-10-08 00:26:08.513813 | controller | skipping: Conditional result was False 2025-10-08 00:26:08.529409 | 2025-10-08 00:26:08.529571 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-08 00:26:08.561277 | controller | skipping: Conditional result was False 2025-10-08 00:26:08.568603 | controller | skipping: Conditional result was False 2025-10-08 00:26:08.606172 | 2025-10-08 00:26:08.606301 | PLAY [localhost] 2025-10-08 00:26:08.621051 | 2025-10-08 00:26:08.621135 | TASK [Run Zuul manifest role] 2025-10-08 00:26:08.640850 | localhost | ok 2025-10-08 00:26:08.658826 | 2025-10-08 00:26:08.658911 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-08 00:26:09.069988 | localhost | changed 2025-10-08 00:26:09.082791 | 2025-10-08 00:26:09.082934 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-08 00:26:09.119630 | localhost | ok 2025-10-08 00:26:09.141184 | 2025-10-08 00:26:09.141360 | TASK [Set zuul-log-path fact] 2025-10-08 00:26:09.195405 | localhost | ok 2025-10-08 00:26:09.208232 | 2025-10-08 00:26:09.208311 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-08 00:26:09.246851 | localhost | ok 2025-10-08 00:26:09.254841 | 2025-10-08 00:26:09.254908 | LOOP [Run upload-logs-swift role] 2025-10-08 00:26:09.291617 | localhost | Output suppressed because no_log was given 2025-10-08 00:26:09.316819 | 2025-10-08 00:26:09.316897 | TASK [Set zuul-log-path fact] 2025-10-08 00:26:09.350778 | localhost | skipping: Conditional result was False 2025-10-08 00:26:09.356337 | 2025-10-08 00:26:09.356415 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-08 00:26:09.788768 | localhost -> localhost | ok: Runtime: 0:00:00.008416 2025-10-08 00:26:09.796138 | 2025-10-08 00:26:09.796255 | TASK [upload-logs-swift : Upload logs to swift]