2025-10-01 10:26:10.770265 | Job console starting... 2025-10-01 10:26:10.783750 | Updating repositories 2025-10-01 10:26:10.805523 | Preparing job workspace 2025-10-01 10:26:14.187484 | Running Ansible setup... 2025-10-01 10:26:19.053565 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-01 10:26:19.725263 | 2025-10-01 10:26:19.725385 | PLAY [localhost] 2025-10-01 10:26:19.740050 | 2025-10-01 10:26:19.740175 | TASK [Gathering Facts] 2025-10-01 10:26:20.777915 | localhost | ok 2025-10-01 10:26:20.791892 | 2025-10-01 10:26:20.792033 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-01 10:26:21.224339 | localhost -> localhost | changed 2025-10-01 10:26:21.229938 | 2025-10-01 10:26:21.230053 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-01 10:26:22.022707 | localhost -> localhost | changed 2025-10-01 10:26:22.043301 | 2025-10-01 10:26:22.043538 | TASK [Setup log path fact] 2025-10-01 10:26:22.061312 | localhost | ok 2025-10-01 10:26:22.074957 | 2025-10-01 10:26:22.075059 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-01 10:26:22.102511 | localhost | ok 2025-10-01 10:26:22.110570 | 2025-10-01 10:26:22.110636 | TASK [emit-job-header : Print job information] 2025-10-01 10:26:22.141255 | # Job Information 2025-10-01 10:26:22.141411 | Ansible Version: 2.15.12 2025-10-01 10:26:22.141438 | Job: cifmw-molecule-switch_config 2025-10-01 10:26:22.141459 | Pipeline: github-check 2025-10-01 10:26:22.141477 | Executor: ze04.softwarefactory-project.io 2025-10-01 10:26:22.141495 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3237 2025-10-01 10:26:22.141515 | Log URL (when completed): https://logserver.rdoproject.org/ed0/rdoproject.org/ed0e3edbb589474fb11b230374813263/ 2025-10-01 10:26:22.141533 | Event ID: ca1127c0-9eb0-11f0-9508-c017e27814eb 2025-10-01 10:26:22.145206 | 2025-10-01 10:26:22.145270 | LOOP [emit-job-header : Print node information] 2025-10-01 10:26:22.267994 | localhost | ok: 2025-10-01 10:26:22.268444 | localhost | # Node Information 2025-10-01 10:26:22.268511 | localhost | Inventory Hostname: controller 2025-10-01 10:26:22.268564 | localhost | Hostname: np0005464232 2025-10-01 10:26:22.268612 | localhost | Username: zuul 2025-10-01 10:26:22.268661 | localhost | Distro: CentOS 9 2025-10-01 10:26:22.268783 | localhost | Provider: vexxhost-nodepool-tripleo 2025-10-01 10:26:22.268828 | localhost | Region: RegionOne 2025-10-01 10:26:22.268868 | localhost | Label: cloud-centos-9-stream-tripleo 2025-10-01 10:26:22.268909 | localhost | Product Name: OpenStack Nova 2025-10-01 10:26:22.268949 | localhost | Interface IP: 38.129.56.235 2025-10-01 10:26:22.304991 | 2025-10-01 10:26:22.305110 | PLAY [all] 2025-10-01 10:26:22.312590 | 2025-10-01 10:26:22.312665 | TASK [Gather network facts] 2025-10-01 10:26:22.802345 | controller | ok 2025-10-01 10:26:22.825612 | 2025-10-01 10:26:22.825787 | TASK [include_role : start-zuul-console] 2025-10-01 10:26:22.848704 | controller | ok 2025-10-01 10:26:22.865400 | 2025-10-01 10:26:22.865513 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-01 10:26:23.280854 | controller | ok 2025-10-01 10:26:23.290219 | 2025-10-01 10:26:23.290314 | TASK [include_role : add-build-sshkey] 2025-10-01 10:26:23.332303 | controller | ok 2025-10-01 10:26:23.372540 | 2025-10-01 10:26:23.372665 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-01 10:26:23.736642 | controller -> localhost | ok 2025-10-01 10:26:23.744772 | 2025-10-01 10:26:23.744874 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-01 10:26:23.763706 | controller | ok 2025-10-01 10:26:23.780543 | controller | included: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-01 10:26:23.786744 | 2025-10-01 10:26:23.786812 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-01 10:26:24.501340 | controller -> localhost | Generating public/private rsa key pair. 2025-10-01 10:26:24.501526 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/work/ed0e3edbb589474fb11b230374813263_id_rsa. 2025-10-01 10:26:24.501559 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/work/ed0e3edbb589474fb11b230374813263_id_rsa.pub. 2025-10-01 10:26:24.501582 | controller -> localhost | The key fingerprint is: 2025-10-01 10:26:24.501604 | controller -> localhost | SHA256:10POV6Tn6Epr9i93pxPgdWzH3qQ1tLjuz3LzAV3ww2g zuul-build-sshkey 2025-10-01 10:26:24.501626 | controller -> localhost | The key's randomart image is: 2025-10-01 10:26:24.501646 | controller -> localhost | +---[RSA 3072]----+ 2025-10-01 10:26:24.501664 | controller -> localhost | | . .| 2025-10-01 10:26:24.501804 | controller -> localhost | | o* | 2025-10-01 10:26:24.501837 | controller -> localhost | | .E+=*| 2025-10-01 10:26:24.501878 | controller -> localhost | | =o.oB@| 2025-10-01 10:26:24.501901 | controller -> localhost | | S ..=++O=| 2025-10-01 10:26:24.501941 | controller -> localhost | | . .=+ o| 2025-10-01 10:26:24.501965 | controller -> localhost | | o .o | 2025-10-01 10:26:24.501986 | controller -> localhost | | .o=+o=| 2025-10-01 10:26:24.502007 | controller -> localhost | | o+o*OB| 2025-10-01 10:26:24.502027 | controller -> localhost | +----[SHA256]-----+ 2025-10-01 10:26:24.502091 | controller -> localhost | ok: Runtime: 0:00:00.268732 2025-10-01 10:26:24.508055 | 2025-10-01 10:26:24.508122 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-01 10:26:24.527848 | controller | ok 2025-10-01 10:26:24.542307 | controller | included: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-01 10:26:24.550942 | 2025-10-01 10:26:24.551003 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-01 10:26:24.577107 | controller | skipping: Conditional result was False 2025-10-01 10:26:24.583894 | 2025-10-01 10:26:24.583963 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-01 10:26:25.059344 | controller | changed 2025-10-01 10:26:25.081470 | 2025-10-01 10:26:25.081629 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-01 10:26:25.375925 | controller | ok 2025-10-01 10:26:25.389419 | 2025-10-01 10:26:25.389610 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-01 10:26:26.243602 | controller | changed 2025-10-01 10:26:26.255291 | 2025-10-01 10:26:26.255433 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-01 10:26:27.214362 | controller | changed 2025-10-01 10:26:27.219402 | 2025-10-01 10:26:27.219470 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-01 10:26:27.242886 | controller | skipping: Conditional result was False 2025-10-01 10:26:27.248672 | 2025-10-01 10:26:27.248757 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-01 10:26:27.664260 | controller -> localhost | changed 2025-10-01 10:26:27.674764 | 2025-10-01 10:26:27.674840 | TASK [add-build-sshkey : Add back temp key] 2025-10-01 10:26:27.974981 | controller -> localhost | Identity added: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/work/ed0e3edbb589474fb11b230374813263_id_rsa (zuul-build-sshkey) 2025-10-01 10:26:27.975182 | controller -> localhost | ok: Runtime: 0:00:00.013920 2025-10-01 10:26:27.980879 | 2025-10-01 10:26:27.980942 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-01 10:26:28.355467 | controller | ok 2025-10-01 10:26:28.360093 | 2025-10-01 10:26:28.360154 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-01 10:26:28.384873 | controller | skipping: Conditional result was False 2025-10-01 10:26:28.395462 | 2025-10-01 10:26:28.395527 | TASK [include_role : validate-host] 2025-10-01 10:26:28.415578 | controller | ok 2025-10-01 10:26:28.435616 | 2025-10-01 10:26:28.435703 | TASK [validate-host : Define zuul_info_dir fact] 2025-10-01 10:26:28.464525 | controller | ok 2025-10-01 10:26:28.469228 | 2025-10-01 10:26:28.469291 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-10-01 10:26:28.726946 | controller -> localhost | ok 2025-10-01 10:26:28.733526 | 2025-10-01 10:26:28.733599 | TASK [validate-host : Collect information about the host] 2025-10-01 10:26:29.510005 | controller | ok 2025-10-01 10:26:29.527939 | 2025-10-01 10:26:29.528088 | TASK [validate-host : Sanitize hostname] 2025-10-01 10:26:29.616673 | controller | ok 2025-10-01 10:26:29.627175 | 2025-10-01 10:26:29.627312 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-10-01 10:26:30.152413 | controller -> localhost | changed 2025-10-01 10:26:30.158212 | 2025-10-01 10:26:30.158276 | TASK [validate-host : Collect information about zuul worker] 2025-10-01 10:26:30.599089 | controller | ok 2025-10-01 10:26:30.610367 | 2025-10-01 10:26:30.610503 | TASK [validate-host : Write out all zuul information for each host] 2025-10-01 10:26:31.126178 | controller -> localhost | changed 2025-10-01 10:26:31.136356 | 2025-10-01 10:26:31.136423 | TASK [include_role : prepare-workspace-openshift] 2025-10-01 10:26:31.160758 | controller | skipping: Conditional result was False 2025-10-01 10:26:31.165841 | 2025-10-01 10:26:31.165908 | TASK [include_role : remove-zuul-sshkey] 2025-10-01 10:26:31.189667 | controller | skipping: Conditional result was False 2025-10-01 10:26:31.195199 | 2025-10-01 10:26:31.195268 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-01 10:26:31.443313 | controller | ok: "logs" 2025-10-01 10:26:31.443711 | controller | ok: All items complete 2025-10-01 10:26:31.443772 | 2025-10-01 10:26:31.667237 | controller | ok: "artifacts" 2025-10-01 10:26:31.882426 | controller | ok: "docs" 2025-10-01 10:26:31.899711 | 2025-10-01 10:26:31.899871 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-01 10:26:32.154319 | controller | changed: "logs" 2025-10-01 10:26:32.405887 | controller | changed: "artifacts" 2025-10-01 10:26:32.623063 | controller | changed: "docs" 2025-10-01 10:26:32.693897 | 2025-10-01 10:26:32.694000 | PLAY RECAP 2025-10-01 10:26:32.694060 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-01 10:26:32.694097 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-01 10:26:32.694123 | 2025-10-01 10:26:32.923078 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-01 10:26:32.924149 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-01 10:26:33.563214 | 2025-10-01 10:26:33.563329 | PLAY [localhost] 2025-10-01 10:26:33.579295 | 2025-10-01 10:26:33.579373 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-10-01 10:26:34.042801 | localhost | ok 2025-10-01 10:26:34.050977 | 2025-10-01 10:26:34.051178 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-10-01 10:26:34.955274 | localhost | changed 2025-10-01 10:26:35.001133 | 2025-10-01 10:26:35.001217 | PLAY [all] 2025-10-01 10:26:35.043618 | 2025-10-01 10:26:35.043773 | TASK [include_role : prepare-workspace] 2025-10-01 10:26:35.078845 | controller | ok 2025-10-01 10:26:35.110431 | 2025-10-01 10:26:35.110563 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-01 10:26:35.550238 | controller | ok 2025-10-01 10:26:35.556838 | 2025-10-01 10:26:35.556900 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-01 10:26:37.769371 | controller | Output suppressed because no_log was given 2025-10-01 10:26:37.786156 | 2025-10-01 10:26:37.786325 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-01 10:26:38.020740 | controller | changed: "logs" 2025-10-01 10:26:38.233702 | controller | changed: "artifacts" 2025-10-01 10:26:38.445094 | controller | changed: "docs" 2025-10-01 10:26:38.462813 | 2025-10-01 10:26:38.462975 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-01 10:26:38.756994 | controller | changed: "logs" 2025-10-01 10:26:38.757225 | controller | changed: All items complete 2025-10-01 10:26:38.757253 | 2025-10-01 10:26:38.955075 | controller | changed: "artifacts" 2025-10-01 10:26:39.153458 | controller | changed: "docs" 2025-10-01 10:26:39.176610 | 2025-10-01 10:26:39.176788 | TASK [Check if worker can sudo] 2025-10-01 10:26:39.718514 | controller | ok: Runtime: 0:00:00.039460 2025-10-01 10:26:39.728298 | 2025-10-01 10:26:39.728426 | TASK [configure-mirrors : Gather needed facts] 2025-10-01 10:26:39.855590 | controller | skipping: Conditional result was False 2025-10-01 10:26:39.861655 | 2025-10-01 10:26:39.861754 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-10-01 10:26:39.932619 | controller | ok 2025-10-01 10:26:39.954089 | controller | included: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-10-01 10:26:39.961344 | 2025-10-01 10:26:39.961416 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-10-01 10:26:40.351983 | controller | ok 2025-10-01 10:26:40.364225 | 2025-10-01 10:26:40.364351 | LOOP [configure-mirrors : Include OS-specific variables] 2025-10-01 10:26:40.436698 | controller | ok: "/var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-10-01 10:26:40.452774 | 2025-10-01 10:26:40.452856 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-10-01 10:26:41.224117 | controller | changed 2025-10-01 10:26:41.236816 | 2025-10-01 10:26:41.236936 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-10-01 10:26:41.292943 | controller | ok: "/var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-10-01 10:26:41.293176 | controller | ok: All items complete 2025-10-01 10:26:41.293209 | 2025-10-01 10:26:41.349873 | controller | included: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-10-01 10:26:41.356566 | 2025-10-01 10:26:41.356630 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-10-01 10:26:42.253000 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-10-01 10:26:43.099802 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-10-01 10:26:43.118209 | 2025-10-01 10:26:43.118279 | TASK [configure-mirrors : Disable deltrarpm] 2025-10-01 10:26:43.564719 | controller | changed: section and option added 2025-10-01 10:26:43.583562 | 2025-10-01 10:26:43.583628 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-10-01 10:26:44.872615 | controller | 29 files removed 2025-10-01 10:26:44.872851 | controller | ok: Item: dnf clean all Runtime: 0:00:00.923248 2025-10-01 10:26:44.872896 | controller | changed: All items complete 2025-10-01 10:26:44.872917 | 2025-10-01 10:26:55.780966 | controller | Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, groups-manager, needs-restarting, notify-packagekit, playground, repoclosure, repodiff, repograph, repomanage, reposync, system-upgrade 2025-10-01 10:26:55.781093 | controller | DNF version: 4.14.0 2025-10-01 10:26:55.781129 | controller | cachedir: /var/cache/dnf 2025-10-01 10:26:55.781156 | controller | Making cache files for all metadata files. 2025-10-01 10:26:55.781181 | controller | baseos: has expired and will be refreshed. 2025-10-01 10:26:55.781204 | controller | appstream: has expired and will be refreshed. 2025-10-01 10:26:55.781227 | controller | crb: has expired and will be refreshed. 2025-10-01 10:26:55.781381 | controller | extras-common: has expired and will be refreshed. 2025-10-01 10:26:55.781413 | controller | repo: downloading from remote: baseos 2025-10-01 10:26:55.781432 | controller | CentOS Stream 9 - BaseOS 33 MB/s | 8.8 MB 00:00 2025-10-01 10:26:55.781451 | controller | baseos: using metadata from Tue 30 Sep 2025 01:12:56 PM EDT. 2025-10-01 10:26:55.781468 | controller | repo: downloading from remote: appstream 2025-10-01 10:26:55.781495 | controller | CentOS Stream 9 - AppStream 55 MB/s | 25 MB 00:00 2025-10-01 10:26:55.781524 | controller | appstream: using metadata from Tue 30 Sep 2025 01:16:29 PM EDT. 2025-10-01 10:26:55.781542 | controller | repo: downloading from remote: crb 2025-10-01 10:26:55.781559 | controller | CentOS Stream 9 - CRB 49 MB/s | 7.1 MB 00:00 2025-10-01 10:26:55.781576 | controller | crb: using metadata from Tue 30 Sep 2025 01:20:54 PM EDT. 2025-10-01 10:26:55.781593 | controller | repo: downloading from remote: extras-common 2025-10-01 10:26:55.781609 | controller | CentOS Stream 9 - Extras packages 1.1 MB/s | 20 kB 00:00 2025-10-01 10:26:55.781626 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-10-01 10:26:55.781642 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-10-01 10:26:55.781659 | controller | Completion plugin: Generating completion cache... 2025-10-01 10:26:55.781702 | controller | Metadata cache created. 2025-10-01 10:26:55.781731 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.645331 2025-10-01 10:26:55.807815 | 2025-10-01 10:26:55.807921 | PLAY RECAP 2025-10-01 10:26:55.807965 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-01 10:26:55.807991 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-01 10:26:55.808010 | 2025-10-01 10:26:58.677364 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-01 10:26:58.678263 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-01 10:26:59.279137 | 2025-10-01 10:26:59.279271 | PLAY [all] 2025-10-01 10:26:59.301009 | 2025-10-01 10:26:59.301109 | TASK [Install binary dependencies] 2025-10-01 10:26:59.361093 | controller | ok 2025-10-01 10:26:59.381490 | 2025-10-01 10:26:59.381618 | TASK [bindep : Include find tasks] 2025-10-01 10:26:59.412331 | controller | ok 2025-10-01 10:26:59.420798 | controller | included: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-01 10:26:59.429645 | 2025-10-01 10:26:59.429788 | TASK [bindep : Look for bindep.txt] 2025-10-01 10:26:59.825150 | controller | ok 2025-10-01 10:26:59.834855 | 2025-10-01 10:26:59.834973 | TASK [bindep : Define bindep_file fact] 2025-10-01 10:26:59.890391 | controller | ok 2025-10-01 10:26:59.901107 | 2025-10-01 10:26:59.901214 | TASK [bindep : Look for other-requirements.txt] 2025-10-01 10:26:59.928304 | controller | skipping: Conditional result was False 2025-10-01 10:26:59.934197 | 2025-10-01 10:26:59.934284 | TASK [bindep : Define bindep_file fact] 2025-10-01 10:26:59.958937 | controller | skipping: Conditional result was False 2025-10-01 10:26:59.965100 | 2025-10-01 10:26:59.965180 | TASK [bindep : Look for bindep fallback file] 2025-10-01 10:26:59.989698 | controller | skipping: Conditional result was False 2025-10-01 10:26:59.996068 | 2025-10-01 10:26:59.996160 | TASK [bindep : Define bindep_file fact] 2025-10-01 10:27:00.024814 | controller | skipping: Conditional result was False 2025-10-01 10:27:00.031707 | 2025-10-01 10:27:00.031779 | TASK [bindep : Include bindep tasks] 2025-10-01 10:27:00.062343 | controller | ok 2025-10-01 10:27:00.069611 | controller | included: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-10-01 10:27:00.078746 | 2025-10-01 10:27:00.078904 | TASK [bindep : Look for bindep command] 2025-10-01 10:27:00.107077 | controller | skipping: Conditional result was False 2025-10-01 10:27:00.122326 | 2025-10-01 10:27:00.122451 | TASK [bindep : Check for system bindep] 2025-10-01 10:27:00.656116 | controller | ok: Runtime: 0:00:00.005495 2025-10-01 10:27:00.662441 | 2025-10-01 10:27:00.662516 | TASK [bindep : Define bindep_command fact] 2025-10-01 10:27:00.696393 | controller | skipping: Conditional result was False 2025-10-01 10:27:00.702817 | 2025-10-01 10:27:00.702892 | TASK [bindep : Include install tasks] 2025-10-01 10:27:00.742922 | controller | ok 2025-10-01 10:27:00.751399 | controller | included: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-10-01 10:27:00.761014 | 2025-10-01 10:27:00.761080 | TASK [bindep : Create temp dir for bindep] 2025-10-01 10:27:01.154363 | controller | changed 2025-10-01 10:27:01.162946 | 2025-10-01 10:27:01.163050 | TASK [Ensure we have pip dependencies] 2025-10-01 10:27:01.187361 | controller | ok 2025-10-01 10:27:01.222321 | 2025-10-01 10:27:01.222442 | TASK [ensure-pip : Check if pip is installed] 2025-10-01 06:27:01.516094 | controller | /usr/bin/pip3 2025-10-01 06:27:01.547867 | controller | /usr/bin/python3: No module named wheel 2025-10-01 10:27:01.751952 | controller | ok: Runtime: 0:00:00.045698 2025-10-01 10:27:01.765540 | 2025-10-01 10:27:01.765715 | LOOP [ensure-pip : Install pip from packages] 2025-10-01 10:27:01.817281 | controller | ok: "/var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-10-01 10:27:01.843323 | controller | included: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-10-01 10:27:01.884347 | 2025-10-01 10:27:01.884543 | TASK [ensure-pip : Install Python 3 pip] 2025-10-01 10:27:04.426896 | controller | changed 2025-10-01 10:27:04.435111 | 2025-10-01 10:27:04.435203 | TASK [ensure-pip : Check for EPEL repository] 2025-10-01 10:27:04.506548 | controller | skipping: Conditional result was False 2025-10-01 10:27:04.515335 | 2025-10-01 10:27:04.515432 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-10-01 10:27:04.571365 | controller | skipping: Conditional result was False 2025-10-01 10:27:04.586236 | 2025-10-01 10:27:04.586454 | TASK [ensure-pip : Install Python 2 pip] 2025-10-01 10:27:04.637343 | controller | skipping: Conditional result was False 2025-10-01 10:27:04.652902 | 2025-10-01 10:27:04.653044 | TASK [ensure-pip : Ensure setuptools] 2025-10-01 10:27:04.681425 | controller | skipping: Conditional result was False 2025-10-01 10:27:04.697820 | 2025-10-01 10:27:04.697970 | TASK [ensure-pip : Check for ensurepip module] 2025-10-01 10:27:05.246168 | controller | skipping: Conditional result was False 2025-10-01 10:27:05.257916 | 2025-10-01 10:27:05.258103 | TASK [ensure-pip : Ensure python3-venv] 2025-10-01 10:27:05.285263 | controller | skipping: Conditional result was False 2025-10-01 10:27:05.294856 | 2025-10-01 10:27:05.294979 | TASK [ensure-pip : Install pip from source] 2025-10-01 10:27:05.320328 | controller | skipping: Conditional result was False 2025-10-01 10:27:05.337388 | 2025-10-01 10:27:05.338324 | TASK [ensure-pip : Probe for venv python full path] 2025-10-01 06:27:05.653768 | controller | /usr/bin/python3 2025-10-01 10:27:05.891086 | controller | ok: Runtime: 0:00:00.006737 2025-10-01 10:27:05.904084 | 2025-10-01 10:27:05.904245 | TASK [ensure-pip : Set host default] 2025-10-01 10:27:05.986501 | controller | ok 2025-10-01 10:27:06.000319 | 2025-10-01 10:27:06.000459 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-10-01 10:27:06.072247 | controller | ok 2025-10-01 10:27:06.095383 | 2025-10-01 10:27:06.095523 | TASK [bindep : Install bindep into temporary venv] 2025-10-01 10:27:10.419696 | controller | changed 2025-10-01 10:27:10.425878 | 2025-10-01 10:27:10.425948 | TASK [bindep : Define bindep_command] 2025-10-01 10:27:10.456834 | controller | ok 2025-10-01 10:27:10.463919 | 2025-10-01 10:27:10.464015 | LOOP [bindep : Include package tasks] 2025-10-01 10:27:10.529773 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-10-01 10:27:10.530219 | controller | ok: All items complete 2025-10-01 10:27:10.530247 | 2025-10-01 10:27:10.542311 | controller | included: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-10-01 10:27:10.556800 | 2025-10-01 10:27:10.556901 | TASK [bindep : Define bindep_run fact] 2025-10-01 10:27:10.586626 | controller | ok 2025-10-01 10:27:10.598480 | 2025-10-01 10:27:10.598568 | TASK [bindep : Get list of packages to install from bindep] 2025-10-01 06:27:11.957651 | controller | podman 2025-10-01 06:27:12.010627 | controller | python3-jmespath 2025-10-01 06:27:12.010712 | controller | python3-libvirt 2025-10-01 06:27:12.010723 | controller | python3-lxml 2025-10-01 06:27:12.010735 | controller | python3-netaddr 2025-10-01 10:27:12.132705 | controller | ok: Runtime: 0:00:01.144684 2025-10-01 10:27:12.138332 | 2025-10-01 10:27:12.138400 | TASK [bindep : Install distro packages from bindep] 2025-10-01 10:28:15.496485 | controller | changed 2025-10-01 10:28:15.510837 | 2025-10-01 10:28:15.510991 | TASK [bindep : Check that packages are installed] 2025-10-01 10:28:17.611863 | controller | ok: Runtime: 0:00:01.346281 2025-10-01 10:28:17.624340 | 2025-10-01 10:28:17.624540 | TASK [bindep : Fail if we cannot install all packages] 2025-10-01 10:28:17.651075 | controller | skipping: Conditional result was False 2025-10-01 10:28:17.673394 | 2025-10-01 10:28:17.673509 | TASK [Run test-setup role] 2025-10-01 10:28:17.695546 | controller | ok 2025-10-01 10:28:17.713269 | 2025-10-01 10:28:17.713357 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-01 10:28:18.004742 | controller | ok 2025-10-01 10:28:18.019662 | 2025-10-01 10:28:18.019876 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-01 10:28:18.569217 | controller | skipping: Conditional result was False 2025-10-01 10:28:18.596443 | 2025-10-01 10:28:18.596590 | TASK [bindep : Remove bindep temp dir] 2025-10-01 10:28:18.990861 | controller | ok 2025-10-01 10:28:19.016013 | 2025-10-01 10:28:19.016161 | PLAY RECAP 2025-10-01 10:28:19.016243 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-10-01 10:28:19.016287 | 2025-10-01 10:28:19.150355 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-01 10:28:19.151259 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-01 10:28:19.733622 | 2025-10-01 10:28:19.733768 | PLAY [all] 2025-10-01 10:28:19.754399 | 2025-10-01 10:28:19.754486 | TASK [Abort when test_command variable is undefined] 2025-10-01 10:28:19.789335 | controller | skipping: Conditional result was False 2025-10-01 10:28:19.795458 | 2025-10-01 10:28:19.795532 | TASK [Convert test_command to list] 2025-10-01 10:28:19.860501 | controller | skipping: Conditional result was False 2025-10-01 10:28:19.866804 | 2025-10-01 10:28:19.866871 | TASK [Use test_command list] 2025-10-01 10:28:19.951144 | controller | ok 2025-10-01 10:28:19.959885 | 2025-10-01 10:28:19.959988 | LOOP [Run test_command] 2025-10-01 10:28:20.397166 | controller | no check to run 2025-10-01 10:28:20.397495 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.007100 2025-10-01 10:28:20.441547 | 2025-10-01 10:28:20.441640 | PLAY RECAP 2025-10-01 10:28:20.441720 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-01 10:28:20.441749 | 2025-10-01 10:28:20.538473 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-01 10:28:20.539789 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-01 10:28:21.125089 | 2025-10-01 10:28:21.125221 | PLAY [all] 2025-10-01 10:28:21.153311 | 2025-10-01 10:28:21.153451 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-01 10:28:21.651135 | controller | changed: non-zero return code 2025-10-01 10:28:21.656581 | 2025-10-01 10:28:21.656654 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-01 10:28:21.670982 | controller | skipping: Conditional result was False 2025-10-01 10:28:21.677425 | 2025-10-01 10:28:21.677504 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-01 10:28:21.708088 | 2025-10-01 10:28:21.708224 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-01 10:28:21.728054 | 2025-10-01 10:28:21.728173 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-01 10:28:21.741721 | controller | skipping: Conditional result was False 2025-10-01 10:28:21.748339 | 2025-10-01 10:28:21.748423 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-01 10:28:21.775979 | 2025-10-01 10:28:21.776113 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-01 10:28:21.789612 | controller | skipping: Conditional result was False 2025-10-01 10:28:21.795427 | 2025-10-01 10:28:21.795493 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-01 10:28:21.808787 | controller | skipping: Conditional result was False 2025-10-01 10:28:21.814404 | 2025-10-01 10:28:21.814474 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-01 10:28:21.827995 | controller | skipping: Conditional result was False 2025-10-01 10:28:21.853024 | 2025-10-01 10:28:21.853084 | PLAY RECAP 2025-10-01 10:28:21.853126 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-01 10:28:21.853146 | 2025-10-01 10:28:21.939284 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-01 10:28:21.940419 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-01 10:28:22.520170 | 2025-10-01 10:28:22.520303 | PLAY [all] 2025-10-01 10:28:22.541354 | 2025-10-01 10:28:22.541480 | TASK [include_role : fetch-output] 2025-10-01 10:28:22.604329 | controller | ok 2025-10-01 10:28:22.623022 | 2025-10-01 10:28:22.623157 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-01 10:28:22.677951 | controller | skipping: Conditional result was False 2025-10-01 10:28:22.683989 | 2025-10-01 10:28:22.684063 | TASK [fetch-output : Set log path for single node] 2025-10-01 10:28:22.717935 | controller | ok 2025-10-01 10:28:22.722885 | 2025-10-01 10:28:22.722950 | LOOP [fetch-output : Ensure local output dirs] 2025-10-01 10:28:23.118884 | controller -> localhost | ok: "/var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/work/logs" 2025-10-01 10:28:23.359982 | controller -> localhost | changed: "/var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/work/artifacts" 2025-10-01 10:28:23.595828 | controller -> localhost | changed: "/var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/work/docs" 2025-10-01 10:28:23.615562 | 2025-10-01 10:28:23.615739 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-01 10:28:24.333888 | controller | changed: .d..t...... ./ 2025-10-01 10:28:24.334162 | controller | changed: All items complete 2025-10-01 10:28:24.334202 | 2025-10-01 10:28:24.861790 | controller | changed: .d..t...... ./ 2025-10-01 10:28:25.391788 | controller | changed: .d..t...... ./ 2025-10-01 10:28:25.420907 | 2025-10-01 10:28:25.421001 | TASK [include_role : fetch-output-openshift] 2025-10-01 10:28:25.445030 | controller | skipping: Conditional result was False 2025-10-01 10:28:25.451495 | 2025-10-01 10:28:25.451568 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-01 10:28:25.844144 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.007484 2025-10-01 10:28:26.079864 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.008169 2025-10-01 10:28:26.109380 | 2025-10-01 10:28:26.109481 | PLAY [all] 2025-10-01 10:28:26.123500 | 2025-10-01 10:28:26.123568 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-10-01 10:28:26.632150 | controller | changed 2025-10-01 10:28:26.675390 | 2025-10-01 10:28:26.675465 | PLAY RECAP 2025-10-01 10:28:26.675521 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-01 10:28:26.675549 | 2025-10-01 10:28:26.808327 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-01 10:28:26.809187 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-10-01 10:28:27.474474 | 2025-10-01 10:28:27.474583 | PLAY [localhost] 2025-10-01 10:28:27.492781 | 2025-10-01 10:28:27.492866 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-01 10:28:27.865311 | localhost | changed 2025-10-01 10:28:27.871170 | 2025-10-01 10:28:27.871250 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-01 10:28:27.908718 | localhost | ok 2025-10-01 10:28:27.916603 | 2025-10-01 10:28:27.916672 | TASK [add-fileserver : Create SSH private key tempfile] 2025-10-01 10:28:28.371031 | localhost | changed 2025-10-01 10:28:28.377027 | 2025-10-01 10:28:28.377099 | TASK [add-fileserver : Create SSH private key from secret] 2025-10-01 10:28:29.063037 | localhost | changed 2025-10-01 10:28:29.074653 | 2025-10-01 10:28:29.074985 | TASK [add-fileserver : Add fileserver ssh key] 2025-10-01 10:28:29.545405 | localhost | Identity added: /var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/work/tmp/ansible.gmokbp_9 (/var/lib/zuul/builds/ed0e3edbb589474fb11b230374813263/work/tmp/ansible.gmokbp_9) 2025-10-01 10:28:29.545615 | localhost | ok: Runtime: 0:00:00.013417 2025-10-01 10:28:29.550069 | 2025-10-01 10:28:29.550138 | TASK [add-fileserver : Remove SSH private key from disk] 2025-10-01 10:28:29.814899 | localhost | ok: Runtime: 0:00:00.009107 2025-10-01 10:28:29.819985 | 2025-10-01 10:28:29.820051 | TASK [add-fileserver : Add fileserver to inventory] 2025-10-01 10:28:29.906733 | localhost | changed 2025-10-01 10:28:29.916374 | 2025-10-01 10:28:29.916516 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-10-01 10:28:30.369447 | localhost | changed 2025-10-01 10:28:30.389099 | 2025-10-01 10:28:30.389166 | PLAY [localhost] 2025-10-01 10:28:30.401474 | 2025-10-01 10:28:30.401539 | TASK [Generate bulk log download script] 2025-10-01 10:28:30.420128 | localhost | ok 2025-10-01 10:28:30.432413 | 2025-10-01 10:28:30.432486 | TASK [local-log-download : Check API endpoint is defined] 2025-10-01 10:28:30.481719 | localhost | ok: All assertions passed 2025-10-01 10:28:30.488095 | 2025-10-01 10:28:30.488179 | TASK [local-log-download : Create download script] 2025-10-01 10:28:30.973956 | localhost -> localhost | changed 2025-10-01 10:28:30.997285 | 2025-10-01 10:28:30.997454 | TASK [Register quick-download link] 2025-10-01 10:28:31.023155 | localhost | ok 2025-10-01 10:28:31.082546 | 2025-10-01 10:28:31.082653 | PLAY [logserver.rdoproject.org] 2025-10-01 10:28:31.092708 | 2025-10-01 10:28:31.092770 | TASK [Set zuul-log-path fact] 2025-10-01 10:28:31.109435 | logserver.rdoproject.org | ok 2025-10-01 10:28:31.119476 | 2025-10-01 10:28:31.119542 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-01 10:28:31.146690 | logserver.rdoproject.org | ok 2025-10-01 10:28:31.152020 | 2025-10-01 10:28:31.152089 | TASK [upload-logs : Create log directories] 2025-10-01 10:28:31.761443 | logserver.rdoproject.org | changed 2025-10-01 10:28:31.768891 | 2025-10-01 10:28:31.769054 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-10-01 10:28:32.113610 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.008826 2025-10-01 10:28:32.123420 | 2025-10-01 10:28:32.123576 | TASK [upload-logs : Upload logs to log server] 2025-10-01 10:28:32.788285 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-10-01 10:28:32.792338 | 2025-10-01 10:28:32.792423 | LOOP [upload-logs : Compress console log and json output] 2025-10-01 10:28:32.858341 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-01 10:28:32.863600 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-01 10:28:32.876402 | 2025-10-01 10:28:32.876478 | LOOP [upload-logs : Upload compressed console log and json output] 2025-10-01 10:28:32.916801 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-01 10:28:32.917026 | 2025-10-01 10:28:32.921811 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-01 10:28:32.933973 | 2025-10-01 10:28:32.934051 | LOOP [upload-logs : Upload console log and json output]