2025-11-26 07:30:11.703490 | Job console starting... 2025-11-26 07:30:11.720990 | Updating repositories 2025-11-26 07:30:11.759339 | Preparing job workspace 2025-11-26 07:30:15.737334 | Running Ansible setup... 2025-11-26 07:30:19.761897 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-11-26 07:30:20.351185 | 2025-11-26 07:30:20.351319 | PLAY [localhost] 2025-11-26 07:30:20.360823 | 2025-11-26 07:30:20.360913 | TASK [Gathering Facts] 2025-11-26 07:30:21.432007 | localhost | ok 2025-11-26 07:30:21.452476 | 2025-11-26 07:30:21.452649 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-26 07:30:21.856772 | localhost -> localhost | changed 2025-11-26 07:30:21.862908 | 2025-11-26 07:30:21.862981 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-26 07:30:22.703633 | localhost -> localhost | changed 2025-11-26 07:30:22.727460 | 2025-11-26 07:30:22.727581 | TASK [Setup log path fact] 2025-11-26 07:30:22.748067 | localhost | ok 2025-11-26 07:30:22.760930 | 2025-11-26 07:30:22.760999 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-26 07:30:22.782614 | localhost | ok 2025-11-26 07:30:22.790766 | 2025-11-26 07:30:22.790835 | TASK [emit-job-header : Print job information] 2025-11-26 07:30:22.831065 | # Job Information 2025-11-26 07:30:22.831223 | Ansible Version: 2.15.12 2025-11-26 07:30:22.831248 | Job: cifmw-molecule-cifmw_setup 2025-11-26 07:30:22.831268 | Pipeline: github-check 2025-11-26 07:30:22.831285 | Executor: ze02.softwarefactory-project.io 2025-11-26 07:30:22.831302 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3505 2025-11-26 07:30:22.831319 | Log URL (when completed): https://logserver.rdoproject.org/829/rdoproject.org/829ac82617164038aaa7fab961cc45bb/ 2025-11-26 07:30:22.831336 | Event ID: 8adaaf80-ca99-11f0-898f-2010a17eda0e 2025-11-26 07:30:22.835154 | 2025-11-26 07:30:22.835220 | LOOP [emit-job-header : Print node information] 2025-11-26 07:30:22.935463 | localhost | ok: 2025-11-26 07:30:22.935762 | localhost | # Node Information 2025-11-26 07:30:22.935794 | localhost | Inventory Hostname: controller 2025-11-26 07:30:22.935817 | localhost | Hostname: np0005536202 2025-11-26 07:30:22.935836 | localhost | Username: zuul 2025-11-26 07:30:22.935855 | localhost | Distro: CentOS 9 2025-11-26 07:30:22.935872 | localhost | Provider: vexxhost-nodepool-tripleo 2025-11-26 07:30:22.935889 | localhost | Region: RegionOne 2025-11-26 07:30:22.935905 | localhost | Label: cloud-centos-9-stream-tripleo 2025-11-26 07:30:22.935921 | localhost | Product Name: OpenStack Nova 2025-11-26 07:30:22.935937 | localhost | Interface IP: 38.102.83.136 2025-11-26 07:30:22.963201 | 2025-11-26 07:30:22.963334 | PLAY [all] 2025-11-26 07:30:22.970798 | 2025-11-26 07:30:22.970864 | TASK [Gather network facts] 2025-11-26 07:30:23.458822 | controller | ok 2025-11-26 07:30:23.480759 | 2025-11-26 07:30:23.480905 | TASK [include_role : start-zuul-console] 2025-11-26 07:30:23.524906 | controller | ok 2025-11-26 07:30:23.537951 | 2025-11-26 07:30:23.538028 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-26 07:30:24.027202 | controller | ok 2025-11-26 07:30:24.046284 | 2025-11-26 07:30:24.046569 | TASK [include_role : add-build-sshkey] 2025-11-26 07:30:24.083384 | controller | ok 2025-11-26 07:30:24.099258 | 2025-11-26 07:30:24.099417 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-26 07:30:24.360039 | controller -> localhost | ok 2025-11-26 07:30:24.367971 | 2025-11-26 07:30:24.368060 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-26 07:30:24.400231 | controller | ok 2025-11-26 07:30:24.423103 | controller | included: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-26 07:30:24.431161 | 2025-11-26 07:30:24.431243 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-26 07:30:25.070059 | controller -> localhost | Generating public/private rsa key pair. 2025-11-26 07:30:25.070320 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/work/829ac82617164038aaa7fab961cc45bb_id_rsa. 2025-11-26 07:30:25.070352 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/work/829ac82617164038aaa7fab961cc45bb_id_rsa.pub. 2025-11-26 07:30:25.070374 | controller -> localhost | The key fingerprint is: 2025-11-26 07:30:25.070394 | controller -> localhost | SHA256:tmJjXMd8UlMoBjrQMNdMJoJ5DYjFWK3f2QBhpK+17MA zuul-build-sshkey 2025-11-26 07:30:25.070413 | controller -> localhost | The key's randomart image is: 2025-11-26 07:30:25.070432 | controller -> localhost | +---[RSA 3072]----+ 2025-11-26 07:30:25.070450 | controller -> localhost | | *o*X*o++. .. | 2025-11-26 07:30:25.070469 | controller -> localhost | |o =o+=o+o o .. | 2025-11-26 07:30:25.070486 | controller -> localhost | | .o .o . .o | 2025-11-26 07:30:25.070504 | controller -> localhost | | .. .. o . . | 2025-11-26 07:30:25.070521 | controller -> localhost | | .o. +S = . | 2025-11-26 07:30:25.070538 | controller -> localhost | | . +.ooo.o o | 2025-11-26 07:30:25.070554 | controller -> localhost | | E o * . | 2025-11-26 07:30:25.070572 | controller -> localhost | | o o o | 2025-11-26 07:30:25.070589 | controller -> localhost | | . | 2025-11-26 07:30:25.070605 | controller -> localhost | +----[SHA256]-----+ 2025-11-26 07:30:25.070655 | controller -> localhost | ok: Runtime: 0:00:00.141681 2025-11-26 07:30:25.077208 | 2025-11-26 07:30:25.077293 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-26 07:30:25.119491 | controller | ok 2025-11-26 07:30:25.131090 | controller | included: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-26 07:30:25.140075 | 2025-11-26 07:30:25.140142 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-26 07:30:25.185941 | controller | skipping: Conditional result was False 2025-11-26 07:30:25.193567 | 2025-11-26 07:30:25.193638 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-26 07:30:25.704366 | controller | changed 2025-11-26 07:30:25.713289 | 2025-11-26 07:30:25.713392 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-26 07:30:25.947062 | controller | ok 2025-11-26 07:30:25.953359 | 2025-11-26 07:30:25.953453 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-26 07:30:26.819182 | controller | changed 2025-11-26 07:30:26.838530 | 2025-11-26 07:30:26.838657 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-26 07:30:27.596604 | controller | changed 2025-11-26 07:30:27.604563 | 2025-11-26 07:30:27.604640 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-26 07:30:27.642469 | controller | skipping: Conditional result was False 2025-11-26 07:30:27.653000 | 2025-11-26 07:30:27.653117 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-26 07:30:28.109935 | controller -> localhost | changed 2025-11-26 07:30:28.120888 | 2025-11-26 07:30:28.120972 | TASK [add-build-sshkey : Add back temp key] 2025-11-26 07:30:28.435738 | controller -> localhost | Identity added: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/work/829ac82617164038aaa7fab961cc45bb_id_rsa (zuul-build-sshkey) 2025-11-26 07:30:28.436031 | controller -> localhost | ok: Runtime: 0:00:00.010516 2025-11-26 07:30:28.442509 | 2025-11-26 07:30:28.442591 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-26 07:30:28.888614 | controller | ok 2025-11-26 07:30:28.902023 | 2025-11-26 07:30:28.902165 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-26 07:30:28.950868 | controller | skipping: Conditional result was False 2025-11-26 07:30:28.964972 | 2025-11-26 07:30:28.965062 | TASK [include_role : validate-host] 2025-11-26 07:30:28.997369 | controller | ok 2025-11-26 07:30:29.021932 | 2025-11-26 07:30:29.022098 | TASK [validate-host : Define zuul_info_dir fact] 2025-11-26 07:30:29.064360 | controller | ok 2025-11-26 07:30:29.075512 | 2025-11-26 07:30:29.075745 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-11-26 07:30:29.346661 | controller -> localhost | ok 2025-11-26 07:30:29.353342 | 2025-11-26 07:30:29.353408 | TASK [validate-host : Collect information about the host] 2025-11-26 07:30:30.221260 | controller | ok 2025-11-26 07:30:30.238247 | 2025-11-26 07:30:30.238334 | TASK [validate-host : Sanitize hostname] 2025-11-26 07:30:30.334534 | controller | ok 2025-11-26 07:30:30.346170 | 2025-11-26 07:30:30.346320 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-11-26 07:30:30.885822 | controller -> localhost | changed 2025-11-26 07:30:30.898615 | 2025-11-26 07:30:30.898802 | TASK [validate-host : Collect information about zuul worker] 2025-11-26 07:30:31.291544 | controller | ok 2025-11-26 07:30:31.296749 | 2025-11-26 07:30:31.296868 | TASK [validate-host : Write out all zuul information for each host] 2025-11-26 07:30:31.864290 | controller -> localhost | changed 2025-11-26 07:30:31.879792 | 2025-11-26 07:30:31.879885 | TASK [include_role : prepare-workspace-openshift] 2025-11-26 07:30:31.905976 | controller | skipping: Conditional result was False 2025-11-26 07:30:31.914568 | 2025-11-26 07:30:31.914741 | TASK [include_role : remove-zuul-sshkey] 2025-11-26 07:30:31.943165 | controller | skipping: Conditional result was False 2025-11-26 07:30:31.951622 | 2025-11-26 07:30:31.951751 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-26 07:30:32.197625 | controller | ok: "logs" 2025-11-26 07:30:32.198228 | controller | ok: All items complete 2025-11-26 07:30:32.198291 | 2025-11-26 07:30:32.453850 | controller | ok: "artifacts" 2025-11-26 07:30:32.664932 | controller | ok: "docs" 2025-11-26 07:30:32.678977 | 2025-11-26 07:30:32.679177 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-26 07:30:32.949924 | controller | changed: "logs" 2025-11-26 07:30:33.182571 | controller | changed: "artifacts" 2025-11-26 07:30:33.409413 | controller | changed: "docs" 2025-11-26 07:30:33.459615 | 2025-11-26 07:30:33.459814 | PLAY RECAP 2025-11-26 07:30:33.459878 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-11-26 07:30:33.459915 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-26 07:30:33.459941 | 2025-11-26 07:30:33.639606 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-11-26 07:30:33.640470 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-11-26 07:30:34.263511 | 2025-11-26 07:30:34.263746 | PLAY [localhost] 2025-11-26 07:30:34.280512 | 2025-11-26 07:30:34.280590 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-11-26 07:30:34.808027 | localhost | ok 2025-11-26 07:30:34.815091 | 2025-11-26 07:30:34.815228 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-11-26 07:30:35.438490 | localhost | changed 2025-11-26 07:30:35.461990 | 2025-11-26 07:30:35.462063 | PLAY [all] 2025-11-26 07:30:35.478356 | 2025-11-26 07:30:35.478442 | TASK [include_role : prepare-workspace] 2025-11-26 07:30:35.508988 | controller | ok 2025-11-26 07:30:35.524052 | 2025-11-26 07:30:35.524125 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-26 07:30:35.955631 | controller | ok 2025-11-26 07:30:35.964136 | 2025-11-26 07:30:35.964261 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-26 07:30:37.639122 | controller | Output suppressed because no_log was given 2025-11-26 07:30:37.649618 | 2025-11-26 07:30:37.649714 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-26 07:30:37.922433 | controller | changed: "logs" 2025-11-26 07:30:38.165652 | controller | changed: "artifacts" 2025-11-26 07:30:38.423795 | controller | changed: "docs" 2025-11-26 07:30:38.445472 | 2025-11-26 07:30:38.445622 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-26 07:30:38.743201 | controller | changed: "logs" 2025-11-26 07:30:38.743653 | controller | changed: All items complete 2025-11-26 07:30:38.743774 | 2025-11-26 07:30:38.957660 | controller | changed: "artifacts" 2025-11-26 07:30:39.154256 | controller | changed: "docs" 2025-11-26 07:30:39.176795 | 2025-11-26 07:30:39.176976 | TASK [Check if worker can sudo] 2025-11-26 07:30:39.744177 | controller | ok: Runtime: 0:00:00.046756 2025-11-26 07:30:39.750685 | 2025-11-26 07:30:39.750820 | TASK [configure-mirrors : Gather needed facts] 2025-11-26 07:30:39.807133 | controller | skipping: Conditional result was False 2025-11-26 07:30:39.813985 | 2025-11-26 07:30:39.814097 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-11-26 07:30:39.879225 | controller | ok 2025-11-26 07:30:39.894111 | controller | included: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-11-26 07:30:39.905841 | 2025-11-26 07:30:39.906034 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-11-26 07:30:40.315160 | controller | ok 2025-11-26 07:30:40.322760 | 2025-11-26 07:30:40.322833 | LOOP [configure-mirrors : Include OS-specific variables] 2025-11-26 07:30:40.397714 | controller | ok: "/var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-11-26 07:30:40.406260 | 2025-11-26 07:30:40.406412 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-11-26 07:30:41.328488 | controller | changed 2025-11-26 07:30:41.334859 | 2025-11-26 07:30:41.334940 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-11-26 07:30:41.388833 | controller | ok: "/var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-11-26 07:30:41.389023 | controller | ok: All items complete 2025-11-26 07:30:41.389050 | 2025-11-26 07:30:41.445139 | controller | included: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-11-26 07:30:41.452628 | 2025-11-26 07:30:41.452740 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-11-26 07:30:42.386023 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-11-26 07:30:43.184470 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-11-26 07:30:43.194695 | 2025-11-26 07:30:43.194831 | TASK [configure-mirrors : Disable deltrarpm] 2025-11-26 07:30:43.654292 | controller | changed: section and option added 2025-11-26 07:30:43.696785 | 2025-11-26 07:30:43.696960 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-11-26 07:30:44.487850 | controller | 29 files removed 2025-11-26 07:30:44.488111 | controller | ok: Item: dnf clean all Runtime: 0:00:00.484428 2025-11-26 07:30:44.488153 | controller | changed: All items complete 2025-11-26 07:30:44.488174 | 2025-11-26 07:30:55.622219 | controller | Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, groups-manager, needs-restarting, playground, repoclosure, repodiff, repograph, repomanage, reposync, system-upgrade 2025-11-26 07:30:55.622412 | controller | DNF version: 4.14.0 2025-11-26 07:30:55.622438 | controller | cachedir: /var/cache/dnf 2025-11-26 07:30:55.622457 | controller | Making cache files for all metadata files. 2025-11-26 07:30:55.622476 | controller | baseos: has expired and will be refreshed. 2025-11-26 07:30:55.622493 | controller | appstream: has expired and will be refreshed. 2025-11-26 07:30:55.622510 | controller | crb: has expired and will be refreshed. 2025-11-26 07:30:55.622537 | controller | extras-common: has expired and will be refreshed. 2025-11-26 07:30:55.622554 | controller | repo: downloading from remote: baseos 2025-11-26 07:30:55.622571 | controller | CentOS Stream 9 - BaseOS 74 MB/s | 8.8 MB 00:00 2025-11-26 07:30:55.622587 | controller | baseos: using metadata from Mon 24 Nov 2025 12:32:03 PM EST. 2025-11-26 07:30:55.622604 | controller | repo: downloading from remote: appstream 2025-11-26 07:30:55.622620 | controller | CentOS Stream 9 - AppStream 97 MB/s | 25 MB 00:00 2025-11-26 07:30:55.622636 | controller | appstream: using metadata from Mon 24 Nov 2025 12:35:27 PM EST. 2025-11-26 07:30:55.622652 | controller | repo: downloading from remote: crb 2025-11-26 07:30:55.622695 | controller | CentOS Stream 9 - CRB 53 MB/s | 7.3 MB 00:00 2025-11-26 07:30:55.622713 | controller | crb: using metadata from Mon 24 Nov 2025 12:39:46 PM EST. 2025-11-26 07:30:55.622730 | controller | repo: downloading from remote: extras-common 2025-11-26 07:30:55.622746 | controller | CentOS Stream 9 - Extras packages 1.7 MB/s | 20 kB 00:00 2025-11-26 07:30:55.622763 | controller | extras-common: using metadata from Thu 30 Oct 2025 09:20:08 AM EDT. 2025-11-26 07:30:55.622779 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-11-26 07:30:55.622796 | controller | Completion plugin: Generating completion cache... 2025-11-26 07:30:55.622812 | controller | Metadata cache created. 2025-11-26 07:30:55.622839 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.844274 2025-11-26 07:30:55.643090 | 2025-11-26 07:30:55.643216 | PLAY RECAP 2025-11-26 07:30:55.643258 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-11-26 07:30:55.643284 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-26 07:30:55.643302 | 2025-11-26 07:30:55.806920 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-11-26 07:30:55.808281 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-26 07:30:56.442386 | 2025-11-26 07:30:56.442524 | PLAY [all] 2025-11-26 07:30:56.464810 | 2025-11-26 07:30:56.465021 | TASK [Install binary dependencies] 2025-11-26 07:30:56.521910 | controller | ok 2025-11-26 07:30:56.542360 | 2025-11-26 07:30:56.542456 | TASK [bindep : Include find tasks] 2025-11-26 07:30:56.583723 | controller | ok 2025-11-26 07:30:56.591330 | controller | included: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-26 07:30:56.600484 | 2025-11-26 07:30:56.600572 | TASK [bindep : Look for bindep.txt] 2025-11-26 07:30:57.026312 | controller | ok 2025-11-26 07:30:57.035992 | 2025-11-26 07:30:57.036096 | TASK [bindep : Define bindep_file fact] 2025-11-26 07:30:57.069708 | controller | ok 2025-11-26 07:30:57.077556 | 2025-11-26 07:30:57.077633 | TASK [bindep : Look for other-requirements.txt] 2025-11-26 07:30:57.102022 | controller | skipping: Conditional result was False 2025-11-26 07:30:57.108850 | 2025-11-26 07:30:57.108923 | TASK [bindep : Define bindep_file fact] 2025-11-26 07:30:57.154742 | controller | skipping: Conditional result was False 2025-11-26 07:30:57.162197 | 2025-11-26 07:30:57.162308 | TASK [bindep : Look for bindep fallback file] 2025-11-26 07:30:57.210954 | controller | skipping: Conditional result was False 2025-11-26 07:30:57.217689 | 2025-11-26 07:30:57.217822 | TASK [bindep : Define bindep_file fact] 2025-11-26 07:30:57.246979 | controller | skipping: Conditional result was False 2025-11-26 07:30:57.254769 | 2025-11-26 07:30:57.254842 | TASK [bindep : Include bindep tasks] 2025-11-26 07:30:57.286400 | controller | ok 2025-11-26 07:30:57.295864 | controller | included: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-11-26 07:30:57.303994 | 2025-11-26 07:30:57.304069 | TASK [bindep : Look for bindep command] 2025-11-26 07:30:57.328533 | controller | skipping: Conditional result was False 2025-11-26 07:30:57.335491 | 2025-11-26 07:30:57.335566 | TASK [bindep : Check for system bindep] 2025-11-26 07:30:57.870122 | controller | ok: Runtime: 0:00:00.004994 2025-11-26 07:30:57.875901 | 2025-11-26 07:30:57.875968 | TASK [bindep : Define bindep_command fact] 2025-11-26 07:30:57.901038 | controller | skipping: Conditional result was False 2025-11-26 07:30:57.907593 | 2025-11-26 07:30:57.907692 | TASK [bindep : Include install tasks] 2025-11-26 07:30:57.947705 | controller | ok 2025-11-26 07:30:57.965788 | controller | included: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-11-26 07:30:57.975708 | 2025-11-26 07:30:57.975775 | TASK [bindep : Create temp dir for bindep] 2025-11-26 07:30:58.417613 | controller | changed 2025-11-26 07:30:58.424285 | 2025-11-26 07:30:58.424352 | TASK [Ensure we have pip dependencies] 2025-11-26 07:30:58.455437 | controller | ok 2025-11-26 07:30:58.482628 | 2025-11-26 07:30:58.482735 | TASK [ensure-pip : Check if pip is installed] 2025-11-26 02:30:58.765612 | controller | /usr/bin/pip3 2025-11-26 02:30:58.787886 | controller | /usr/bin/python3: No module named wheel 2025-11-26 07:30:59.012053 | controller | ok: Runtime: 0:00:00.033442 2025-11-26 07:30:59.025772 | 2025-11-26 07:30:59.025930 | LOOP [ensure-pip : Install pip from packages] 2025-11-26 07:30:59.063803 | controller | ok: "/var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-11-26 07:30:59.081173 | controller | included: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-11-26 07:30:59.095876 | 2025-11-26 07:30:59.095960 | TASK [ensure-pip : Install Python 3 pip] 2025-11-26 07:31:01.216323 | controller | changed 2025-11-26 07:31:01.223819 | 2025-11-26 07:31:01.224081 | TASK [ensure-pip : Check for EPEL repository] 2025-11-26 07:31:01.260303 | controller | skipping: Conditional result was False 2025-11-26 07:31:01.268518 | 2025-11-26 07:31:01.268600 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-11-26 07:31:01.314217 | controller | skipping: Conditional result was False 2025-11-26 07:31:01.322064 | 2025-11-26 07:31:01.322142 | TASK [ensure-pip : Install Python 2 pip] 2025-11-26 07:31:01.367290 | controller | skipping: Conditional result was False 2025-11-26 07:31:01.374888 | 2025-11-26 07:31:01.374963 | TASK [ensure-pip : Ensure setuptools] 2025-11-26 07:31:01.392033 | controller | skipping: Conditional result was False 2025-11-26 07:31:01.400643 | 2025-11-26 07:31:01.400796 | TASK [ensure-pip : Check for ensurepip module] 2025-11-26 07:31:01.931797 | controller | skipping: Conditional result was False 2025-11-26 07:31:01.939061 | 2025-11-26 07:31:01.939173 | TASK [ensure-pip : Ensure python3-venv] 2025-11-26 07:31:01.986782 | controller | skipping: Conditional result was False 2025-11-26 07:31:01.993877 | 2025-11-26 07:31:01.993966 | TASK [ensure-pip : Install pip from source] 2025-11-26 07:31:02.022032 | controller | skipping: Conditional result was False 2025-11-26 07:31:02.028433 | 2025-11-26 07:31:02.028627 | TASK [ensure-pip : Probe for venv python full path] 2025-11-26 02:31:02.292536 | controller | /usr/bin/python3 2025-11-26 07:31:02.559363 | controller | ok: Runtime: 0:00:00.004196 2025-11-26 07:31:02.566334 | 2025-11-26 07:31:02.566405 | TASK [ensure-pip : Set host default] 2025-11-26 07:31:02.642200 | controller | ok 2025-11-26 07:31:02.651347 | 2025-11-26 07:31:02.651548 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-11-26 07:31:02.704067 | controller | ok 2025-11-26 07:31:02.716046 | 2025-11-26 07:31:02.716158 | TASK [bindep : Install bindep into temporary venv] 2025-11-26 07:31:06.960512 | controller | changed 2025-11-26 07:31:06.968655 | 2025-11-26 07:31:06.968793 | TASK [bindep : Define bindep_command] 2025-11-26 07:31:07.003347 | controller | ok 2025-11-26 07:31:07.010922 | 2025-11-26 07:31:07.011001 | LOOP [bindep : Include package tasks] 2025-11-26 07:31:07.092363 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-11-26 07:31:07.092734 | controller | ok: All items complete 2025-11-26 07:31:07.092772 | 2025-11-26 07:31:07.153047 | controller | included: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-11-26 07:31:07.167444 | 2025-11-26 07:31:07.167514 | TASK [bindep : Define bindep_run fact] 2025-11-26 07:31:07.209386 | controller | ok 2025-11-26 07:31:07.215446 | 2025-11-26 07:31:07.215516 | TASK [bindep : Get list of packages to install from bindep] 2025-11-26 02:31:08.578975 | controller | podman 2025-11-26 02:31:08.610385 | controller | python3-jmespath 2025-11-26 02:31:08.610438 | controller | python3-libvirt 2025-11-26 02:31:08.610446 | controller | python3-lxml 2025-11-26 02:31:08.610524 | controller | python3-netaddr 2025-11-26 07:31:08.750748 | controller | ok: Runtime: 0:00:01.149725 2025-11-26 07:31:08.756740 | 2025-11-26 07:31:08.756808 | TASK [bindep : Install distro packages from bindep] 2025-11-26 07:32:12.162388 | controller | changed 2025-11-26 07:32:12.175421 | 2025-11-26 07:32:12.175660 | TASK [bindep : Check that packages are installed] 2025-11-26 07:32:13.751555 | controller | ok: Runtime: 0:00:01.191221 2025-11-26 07:32:13.764210 | 2025-11-26 07:32:13.764351 | TASK [bindep : Fail if we cannot install all packages] 2025-11-26 07:32:13.865166 | controller | skipping: Conditional result was False 2025-11-26 07:32:13.929945 | 2025-11-26 07:32:13.930103 | TASK [Run test-setup role] 2025-11-26 07:32:13.964112 | controller | ok 2025-11-26 07:32:13.988174 | 2025-11-26 07:32:13.988286 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-26 07:32:14.253971 | controller | ok 2025-11-26 07:32:14.268354 | 2025-11-26 07:32:14.268577 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-26 07:32:14.816229 | controller | skipping: Conditional result was False 2025-11-26 07:32:14.863981 | 2025-11-26 07:32:14.864171 | TASK [bindep : Remove bindep temp dir] 2025-11-26 07:32:15.254614 | controller | ok 2025-11-26 07:32:15.279361 | 2025-11-26 07:32:15.279529 | PLAY RECAP 2025-11-26 07:32:15.279622 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-11-26 07:32:15.279698 | 2025-11-26 07:32:15.442243 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-26 07:32:15.444710 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-11-26 07:32:16.058066 | 2025-11-26 07:32:16.058226 | PLAY [all] 2025-11-26 07:32:16.078752 | 2025-11-26 07:32:16.078913 | TASK [Abort when test_command variable is undefined] 2025-11-26 07:32:16.115733 | controller | skipping: Conditional result was False 2025-11-26 07:32:16.124170 | 2025-11-26 07:32:16.124314 | TASK [Convert test_command to list] 2025-11-26 07:32:16.183038 | controller | skipping: Conditional result was False 2025-11-26 07:32:16.200602 | 2025-11-26 07:32:16.200838 | TASK [Use test_command list] 2025-11-26 07:32:16.269562 | controller | ok 2025-11-26 07:32:16.277863 | 2025-11-26 07:32:16.277977 | LOOP [Run test_command] 2025-11-26 07:32:16.714526 | controller | no check to run 2025-11-26 07:32:16.715156 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.008148 2025-11-26 07:32:16.753314 | 2025-11-26 07:32:16.753472 | PLAY RECAP 2025-11-26 07:32:16.753530 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-11-26 07:32:16.753559 | 2025-11-26 07:32:16.872166 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-11-26 07:32:16.873067 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-26 07:32:17.445491 | 2025-11-26 07:32:17.445658 | PLAY [all] 2025-11-26 07:32:17.467735 | 2025-11-26 07:32:17.467884 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-26 07:32:17.875697 | controller | changed: non-zero return code 2025-11-26 07:32:17.888657 | 2025-11-26 07:32:17.888865 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-26 07:32:17.918591 | controller | skipping: Conditional result was False 2025-11-26 07:32:17.931937 | 2025-11-26 07:32:17.932134 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-26 07:32:17.977270 | 2025-11-26 07:32:17.977581 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-26 07:32:18.019862 | 2025-11-26 07:32:18.020231 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-26 07:32:18.049508 | controller | skipping: Conditional result was False 2025-11-26 07:32:18.064156 | 2025-11-26 07:32:18.064405 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-26 07:32:18.108987 | 2025-11-26 07:32:18.109329 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-26 07:32:18.138001 | controller | skipping: Conditional result was False 2025-11-26 07:32:18.150807 | 2025-11-26 07:32:18.150982 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-26 07:32:18.179654 | controller | skipping: Conditional result was False 2025-11-26 07:32:18.192236 | 2025-11-26 07:32:18.192385 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-26 07:32:18.220530 | controller | skipping: Conditional result was False 2025-11-26 07:32:18.268826 | 2025-11-26 07:32:18.268924 | PLAY RECAP 2025-11-26 07:32:18.268991 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-26 07:32:18.269027 | 2025-11-26 07:32:18.412263 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-26 07:32:18.413140 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-11-26 07:32:19.088746 | 2025-11-26 07:32:19.088892 | PLAY [all] 2025-11-26 07:32:19.109544 | 2025-11-26 07:32:19.109695 | TASK [include_role : fetch-output] 2025-11-26 07:32:19.162182 | controller | ok 2025-11-26 07:32:19.185712 | 2025-11-26 07:32:19.185818 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-26 07:32:19.264078 | controller | skipping: Conditional result was False 2025-11-26 07:32:19.271191 | 2025-11-26 07:32:19.271267 | TASK [fetch-output : Set log path for single node] 2025-11-26 07:32:19.321011 | controller | ok 2025-11-26 07:32:19.333620 | 2025-11-26 07:32:19.333845 | LOOP [fetch-output : Ensure local output dirs] 2025-11-26 07:32:19.777211 | controller -> localhost | ok: "/var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/work/logs" 2025-11-26 07:32:20.043536 | controller -> localhost | changed: "/var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/work/artifacts" 2025-11-26 07:32:20.324615 | controller -> localhost | changed: "/var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/work/docs" 2025-11-26 07:32:20.349250 | 2025-11-26 07:32:20.349396 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-26 07:32:21.097911 | controller | changed: .d..t...... ./ 2025-11-26 07:32:21.112854 | controller | changed: All items complete 2025-11-26 07:32:21.113003 | 2025-11-26 07:32:21.699923 | controller | changed: .d..t...... ./ 2025-11-26 07:32:22.298768 | controller | changed: .d..t...... ./ 2025-11-26 07:32:22.337092 | 2025-11-26 07:32:22.337333 | TASK [include_role : fetch-output-openshift] 2025-11-26 07:32:22.365154 | controller | skipping: Conditional result was False 2025-11-26 07:32:22.374099 | 2025-11-26 07:32:22.374193 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-26 07:32:22.881165 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.021727 2025-11-26 07:32:23.140546 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.011527 2025-11-26 07:32:23.186084 | 2025-11-26 07:32:23.186260 | PLAY [all] 2025-11-26 07:32:23.211492 | 2025-11-26 07:32:23.211722 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-11-26 07:32:23.729015 | controller | changed 2025-11-26 07:32:23.761879 | 2025-11-26 07:32:23.762030 | PLAY RECAP 2025-11-26 07:32:23.762114 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-11-26 07:32:23.762156 | 2025-11-26 07:32:23.972768 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-11-26 07:32:23.973686 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-11-26 07:32:24.624629 | 2025-11-26 07:32:24.624804 | PLAY [localhost] 2025-11-26 07:32:24.643253 | 2025-11-26 07:32:24.643361 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-26 07:32:25.096409 | localhost | changed 2025-11-26 07:32:25.107113 | 2025-11-26 07:32:25.107276 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-26 07:32:25.148013 | localhost | ok 2025-11-26 07:32:25.172627 | 2025-11-26 07:32:25.172829 | TASK [add-fileserver : Create SSH private key tempfile] 2025-11-26 07:32:25.582449 | localhost | changed 2025-11-26 07:32:25.590593 | 2025-11-26 07:32:25.590744 | TASK [add-fileserver : Create SSH private key from secret] 2025-11-26 07:32:26.374736 | localhost | changed 2025-11-26 07:32:26.391915 | 2025-11-26 07:32:26.392160 | TASK [add-fileserver : Add fileserver ssh key] 2025-11-26 07:32:26.915313 | localhost | Identity added: /var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/work/tmp/ansible.1bwr2zfd (/var/lib/zuul/builds/829ac82617164038aaa7fab961cc45bb/work/tmp/ansible.1bwr2zfd) 2025-11-26 07:32:26.915751 | localhost | ok: Runtime: 0:00:00.012255 2025-11-26 07:32:26.926615 | 2025-11-26 07:32:26.926844 | TASK [add-fileserver : Remove SSH private key from disk] 2025-11-26 07:32:27.262402 | localhost | ok: Runtime: 0:00:00.012388 2025-11-26 07:32:27.275057 | 2025-11-26 07:32:27.275199 | TASK [add-fileserver : Add fileserver to inventory] 2025-11-26 07:32:27.365108 | localhost | changed 2025-11-26 07:32:27.375235 | 2025-11-26 07:32:27.375417 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-11-26 07:32:27.843627 | localhost | changed 2025-11-26 07:32:27.887455 | 2025-11-26 07:32:27.887569 | PLAY [localhost] 2025-11-26 07:32:27.904845 | 2025-11-26 07:32:27.904927 | TASK [Generate bulk log download script] 2025-11-26 07:32:27.927409 | localhost | ok 2025-11-26 07:32:27.944106 | 2025-11-26 07:32:27.944197 | TASK [local-log-download : Check API endpoint is defined] 2025-11-26 07:32:27.986805 | localhost | ok: All assertions passed 2025-11-26 07:32:27.993436 | 2025-11-26 07:32:27.993524 | TASK [local-log-download : Create download script] 2025-11-26 07:32:28.497466 | localhost -> localhost | changed 2025-11-26 07:32:28.506821 | 2025-11-26 07:32:28.506891 | TASK [Register quick-download link] 2025-11-26 07:32:28.536264 | localhost | ok 2025-11-26 07:32:28.587396 | 2025-11-26 07:32:28.587517 | PLAY [logserver.rdoproject.org] 2025-11-26 07:32:28.597333 | 2025-11-26 07:32:28.597416 | TASK [Set zuul-log-path fact] 2025-11-26 07:32:28.615209 | logserver.rdoproject.org | ok 2025-11-26 07:32:28.624466 | 2025-11-26 07:32:28.624631 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-26 07:32:28.653590 | logserver.rdoproject.org | ok 2025-11-26 07:32:28.659246 | 2025-11-26 07:32:28.659314 | TASK [upload-logs : Create log directories] 2025-11-26 07:32:29.427226 | logserver.rdoproject.org | changed 2025-11-26 07:32:29.435040 | 2025-11-26 07:32:29.435181 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-11-26 07:32:29.803308 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.010103 2025-11-26 07:32:29.809643 | 2025-11-26 07:32:29.809799 | TASK [upload-logs : Upload logs to log server] 2025-11-26 07:32:30.530288 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-11-26 07:32:30.533755 | 2025-11-26 07:32:30.533817 | LOOP [upload-logs : Compress console log and json output] 2025-11-26 07:32:30.582368 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-26 07:32:30.593401 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-26 07:32:30.606168 | 2025-11-26 07:32:30.606367 | LOOP [upload-logs : Upload compressed console log and json output] 2025-11-26 07:32:30.649030 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-26 07:32:30.649372 | 2025-11-26 07:32:30.654454 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-26 07:32:30.667070 | 2025-11-26 07:32:30.667248 | LOOP [upload-logs : Upload console log and json output]