2025-11-22 07:51:20.985606 | Job console starting... 2025-11-22 07:51:21.184861 | Updating repositories 2025-11-22 07:51:21.198939 | Preparing job workspace 2025-11-22 07:51:26.499590 | Running Ansible setup... 2025-11-22 07:51:29.335685 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-11-22 07:51:29.842494 | 2025-11-22 07:51:29.842589 | PLAY [localhost] 2025-11-22 07:51:29.850844 | 2025-11-22 07:51:29.850932 | TASK [Gathering Facts] 2025-11-22 07:51:30.636644 | localhost | ok 2025-11-22 07:51:30.650161 | 2025-11-22 07:51:30.650275 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-22 07:51:30.957050 | localhost -> localhost | changed 2025-11-22 07:51:30.963194 | 2025-11-22 07:51:30.963271 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-22 07:51:31.649719 | localhost -> localhost | changed 2025-11-22 07:51:31.657619 | 2025-11-22 07:51:31.657690 | TASK [Setup log path fact] 2025-11-22 07:51:31.674628 | localhost | ok 2025-11-22 07:51:31.685243 | 2025-11-22 07:51:31.685310 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-22 07:51:31.702791 | localhost | ok 2025-11-22 07:51:31.710242 | 2025-11-22 07:51:31.710308 | TASK [emit-job-header : Print job information] 2025-11-22 07:51:31.737235 | # Job Information 2025-11-22 07:51:31.737343 | Ansible Version: 2.15.12 2025-11-22 07:51:31.737372 | Job: cifmw-molecule-cifmw_setup 2025-11-22 07:51:31.737395 | Pipeline: github-check 2025-11-22 07:51:31.737414 | Executor: ibm-bm4-ze.softwarefactory-project.io 2025-11-22 07:51:31.737433 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3497 2025-11-22 07:51:31.737451 | Log URL (when completed): https://logserver.rdoproject.org/def/rdoproject.org/def40741e0c944638e59bf49ece32164/ 2025-11-22 07:51:31.737472 | Event ID: e63453b0-c777-11f0-9e16-5c6fe0fd4294 2025-11-22 07:51:31.740868 | 2025-11-22 07:51:31.740966 | LOOP [emit-job-header : Print node information] 2025-11-22 07:51:31.825376 | localhost | ok: 2025-11-22 07:51:31.825696 | localhost | # Node Information 2025-11-22 07:51:31.825734 | localhost | Inventory Hostname: controller 2025-11-22 07:51:31.825761 | localhost | Hostname: np0005532064 2025-11-22 07:51:31.825783 | localhost | Username: zuul 2025-11-22 07:51:31.825804 | localhost | Distro: CentOS 9 2025-11-22 07:51:31.825824 | localhost | Provider: ibm-bm4-nodepool 2025-11-22 07:51:31.825841 | localhost | Region: regionOne 2025-11-22 07:51:31.825858 | localhost | Label: cloud-centos-9-stream-tripleo 2025-11-22 07:51:31.825876 | localhost | Product Name: OpenStack Compute 2025-11-22 07:51:31.825892 | localhost | Interface IP: 192.168.26.249 2025-11-22 07:51:31.853109 | 2025-11-22 07:51:31.853187 | PLAY [all] 2025-11-22 07:51:31.859840 | 2025-11-22 07:51:31.859904 | TASK [Gather network facts] 2025-11-22 07:51:32.202062 | controller | ok 2025-11-22 07:51:32.215553 | 2025-11-22 07:51:32.215628 | TASK [include_role : start-zuul-console] 2025-11-22 07:51:32.232844 | controller | ok 2025-11-22 07:51:32.244286 | 2025-11-22 07:51:32.244359 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-22 07:51:32.526767 | controller | ok 2025-11-22 07:51:32.535411 | 2025-11-22 07:51:32.535487 | TASK [include_role : add-build-sshkey] 2025-11-22 07:51:32.553217 | controller | ok 2025-11-22 07:51:32.566067 | 2025-11-22 07:51:32.566140 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-22 07:51:32.753347 | controller -> localhost | ok 2025-11-22 07:51:32.758581 | 2025-11-22 07:51:32.758661 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-22 07:51:32.775710 | controller | ok 2025-11-22 07:51:32.788750 | controller | included: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-22 07:51:32.794209 | 2025-11-22 07:51:32.794270 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-22 07:51:33.252317 | controller -> localhost | Generating public/private rsa key pair. 2025-11-22 07:51:33.252504 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/work/def40741e0c944638e59bf49ece32164_id_rsa. 2025-11-22 07:51:33.252541 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/work/def40741e0c944638e59bf49ece32164_id_rsa.pub. 2025-11-22 07:51:33.252566 | controller -> localhost | The key fingerprint is: 2025-11-22 07:51:33.252589 | controller -> localhost | SHA256:l50wHsc1c/JL0lNzIj3Kg8LLtD+CJe58+TGz1M5USHk zuul-build-sshkey 2025-11-22 07:51:33.252610 | controller -> localhost | The key's randomart image is: 2025-11-22 07:51:33.252629 | controller -> localhost | +---[RSA 3072]----+ 2025-11-22 07:51:33.252649 | controller -> localhost | | ..*.+| 2025-11-22 07:51:33.252669 | controller -> localhost | | . ++B+| 2025-11-22 07:51:33.252688 | controller -> localhost | | . +o=oE=.| 2025-11-22 07:51:33.252708 | controller -> localhost | | +..O++o o| 2025-11-22 07:51:33.252728 | controller -> localhost | | oS++ +... | 2025-11-22 07:51:33.252747 | controller -> localhost | | . =. . . | 2025-11-22 07:51:33.252766 | controller -> localhost | | . + o= o | 2025-11-22 07:51:33.252786 | controller -> localhost | | .o +.oO | 2025-11-22 07:51:33.252805 | controller -> localhost | | .o. oo.o | 2025-11-22 07:51:33.252823 | controller -> localhost | +----[SHA256]-----+ 2025-11-22 07:51:33.252865 | controller -> localhost | ok: Runtime: 0:00:00.132945 2025-11-22 07:51:33.258314 | 2025-11-22 07:51:33.258383 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-22 07:51:33.276242 | controller | ok 2025-11-22 07:51:33.285800 | controller | included: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-22 07:51:33.293505 | 2025-11-22 07:51:33.293574 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-22 07:51:33.307071 | controller | skipping: Conditional result was False 2025-11-22 07:51:33.312399 | 2025-11-22 07:51:33.312475 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-22 07:51:33.664156 | controller | changed 2025-11-22 07:51:33.668702 | 2025-11-22 07:51:33.668765 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-22 07:51:33.849504 | controller | ok 2025-11-22 07:51:33.854034 | 2025-11-22 07:51:33.854097 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-22 07:51:34.408721 | controller | changed 2025-11-22 07:51:34.413386 | 2025-11-22 07:51:34.413451 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-22 07:51:35.017719 | controller | changed 2025-11-22 07:51:35.022400 | 2025-11-22 07:51:35.022466 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-22 07:51:35.035669 | controller | skipping: Conditional result was False 2025-11-22 07:51:35.040833 | 2025-11-22 07:51:35.040895 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-22 07:51:35.327160 | controller -> localhost | changed 2025-11-22 07:51:35.337220 | 2025-11-22 07:51:35.337305 | TASK [add-build-sshkey : Add back temp key] 2025-11-22 07:51:35.574438 | controller -> localhost | Identity added: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/work/def40741e0c944638e59bf49ece32164_id_rsa (zuul-build-sshkey) 2025-11-22 07:51:35.574610 | controller -> localhost | ok: Runtime: 0:00:00.007541 2025-11-22 07:51:35.580063 | 2025-11-22 07:51:35.580131 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-22 07:51:35.881689 | controller | ok 2025-11-22 07:51:35.886345 | 2025-11-22 07:51:35.886435 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-22 07:51:35.910501 | controller | skipping: Conditional result was False 2025-11-22 07:51:35.919470 | 2025-11-22 07:51:35.919537 | TASK [include_role : validate-host] 2025-11-22 07:51:35.937119 | controller | ok 2025-11-22 07:51:35.956549 | 2025-11-22 07:51:35.956953 | TASK [validate-host : Define zuul_info_dir fact] 2025-11-22 07:51:35.984484 | controller | ok 2025-11-22 07:51:35.988990 | 2025-11-22 07:51:35.989053 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-11-22 07:51:36.185348 | controller -> localhost | ok 2025-11-22 07:51:36.191185 | 2025-11-22 07:51:36.191256 | TASK [validate-host : Collect information about the host] 2025-11-22 07:51:36.817793 | controller | ok 2025-11-22 07:51:36.825764 | 2025-11-22 07:51:36.825843 | TASK [validate-host : Sanitize hostname] 2025-11-22 07:51:36.893696 | controller | ok 2025-11-22 07:51:36.898526 | 2025-11-22 07:51:36.898601 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-11-22 07:51:37.298298 | controller -> localhost | changed 2025-11-22 07:51:37.320710 | 2025-11-22 07:51:37.320794 | TASK [validate-host : Collect information about zuul worker] 2025-11-22 07:51:37.653796 | controller | ok 2025-11-22 07:51:37.658327 | 2025-11-22 07:51:37.658392 | TASK [validate-host : Write out all zuul information for each host] 2025-11-22 07:51:38.023436 | controller -> localhost | changed 2025-11-22 07:51:38.032188 | 2025-11-22 07:51:38.032249 | TASK [include_role : prepare-workspace-openshift] 2025-11-22 07:51:38.047519 | controller | skipping: Conditional result was False 2025-11-22 07:51:38.052711 | 2025-11-22 07:51:38.052788 | TASK [include_role : remove-zuul-sshkey] 2025-11-22 07:51:38.065680 | controller | skipping: Conditional result was False 2025-11-22 07:51:38.070838 | 2025-11-22 07:51:38.070933 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-22 07:51:38.259874 | controller | ok: "logs" 2025-11-22 07:51:38.260094 | controller | ok: All items complete 2025-11-22 07:51:38.260124 | 2025-11-22 07:51:38.419588 | controller | ok: "artifacts" 2025-11-22 07:51:38.585791 | controller | ok: "docs" 2025-11-22 07:51:38.599384 | 2025-11-22 07:51:38.599536 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-22 07:51:38.800471 | controller | changed: "logs" 2025-11-22 07:51:38.968068 | controller | changed: "artifacts" 2025-11-22 07:51:39.137317 | controller | changed: "docs" 2025-11-22 07:51:39.168754 | 2025-11-22 07:51:39.168854 | PLAY RECAP 2025-11-22 07:51:39.168902 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-11-22 07:51:39.168953 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-22 07:51:39.168975 | 2025-11-22 07:51:39.246103 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-11-22 07:51:39.246836 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-11-22 07:51:39.776471 | 2025-11-22 07:51:39.776566 | PLAY [localhost] 2025-11-22 07:51:39.792046 | 2025-11-22 07:51:39.792125 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-11-22 07:51:40.123786 | localhost | ok 2025-11-22 07:51:40.128809 | 2025-11-22 07:51:40.128927 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-11-22 07:51:40.675276 | localhost | changed 2025-11-22 07:51:40.694833 | 2025-11-22 07:51:40.694926 | PLAY [all] 2025-11-22 07:51:40.710120 | 2025-11-22 07:51:40.710191 | TASK [include_role : prepare-workspace] 2025-11-22 07:51:40.729268 | controller | ok 2025-11-22 07:51:40.742809 | 2025-11-22 07:51:40.742882 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-22 07:51:41.034210 | controller | ok 2025-11-22 07:51:41.039860 | 2025-11-22 07:51:41.039953 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-22 07:51:42.363511 | controller | Output suppressed because no_log was given 2025-11-22 07:51:42.372791 | 2025-11-22 07:51:42.372862 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-22 07:51:42.570954 | controller | changed: "logs" 2025-11-22 07:51:42.741778 | controller | changed: "artifacts" 2025-11-22 07:51:42.919844 | controller | changed: "docs" 2025-11-22 07:51:42.933977 | 2025-11-22 07:51:42.934257 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-22 07:51:43.141887 | controller | changed: "logs" 2025-11-22 07:51:43.142384 | controller | changed: All items complete 2025-11-22 07:51:43.142427 | 2025-11-22 07:51:43.314475 | controller | changed: "artifacts" 2025-11-22 07:51:43.480684 | controller | changed: "docs" 2025-11-22 07:51:43.500113 | 2025-11-22 07:51:43.500266 | TASK [Check if worker can sudo] 2025-11-22 07:51:44.028808 | controller | ok: Runtime: 0:00:00.035482 2025-11-22 07:51:44.044558 | 2025-11-22 07:51:44.044649 | TASK [configure-mirrors : Gather needed facts] 2025-11-22 07:51:44.088871 | controller | skipping: Conditional result was False 2025-11-22 07:51:44.094708 | 2025-11-22 07:51:44.094789 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-11-22 07:51:44.143346 | controller | ok 2025-11-22 07:51:44.150600 | controller | included: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-11-22 07:51:44.155895 | 2025-11-22 07:51:44.155977 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-11-22 07:51:44.356657 | controller | ok 2025-11-22 07:51:44.362465 | 2025-11-22 07:51:44.362551 | LOOP [configure-mirrors : Include OS-specific variables] 2025-11-22 07:51:44.459217 | controller | ok: "/var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-11-22 07:51:44.475470 | 2025-11-22 07:51:44.475558 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-11-22 07:51:45.091378 | controller | changed 2025-11-22 07:51:45.096820 | 2025-11-22 07:51:45.096885 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-11-22 07:51:45.144077 | controller | ok: "/var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-11-22 07:51:45.144233 | controller | ok: All items complete 2025-11-22 07:51:45.144265 | 2025-11-22 07:51:45.187880 | controller | included: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-11-22 07:51:45.194091 | 2025-11-22 07:51:45.194155 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-11-22 07:51:45.852680 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-11-22 07:51:46.447296 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-11-22 07:51:46.460623 | 2025-11-22 07:51:46.460753 | TASK [configure-mirrors : Disable deltrarpm] 2025-11-22 07:51:46.803358 | controller | changed: section and option added 2025-11-22 07:51:46.821722 | 2025-11-22 07:51:46.821807 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-11-22 07:51:47.326545 | controller | 29 files removed 2025-11-22 07:51:47.326768 | controller | ok: Item: dnf clean all Runtime: 0:00:00.274487 2025-11-22 07:51:47.326813 | controller | changed: All items complete 2025-11-22 07:51:47.326836 | 2025-11-22 07:51:55.492840 | 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-22 07:51:55.492963 | controller | DNF version: 4.14.0 2025-11-22 07:51:55.493012 | controller | cachedir: /var/cache/dnf 2025-11-22 07:51:55.493037 | controller | Making cache files for all metadata files. 2025-11-22 07:51:55.493059 | controller | baseos: has expired and will be refreshed. 2025-11-22 07:51:55.493078 | controller | appstream: has expired and will be refreshed. 2025-11-22 07:51:55.493097 | controller | crb: has expired and will be refreshed. 2025-11-22 07:51:55.493131 | controller | extras-common: has expired and will be refreshed. 2025-11-22 07:51:55.493153 | controller | repo: downloading from remote: baseos 2025-11-22 07:51:55.493171 | controller | CentOS Stream 9 - BaseOS 105 MB/s | 8.8 MB 00:00 2025-11-22 07:51:55.493200 | controller | baseos: using metadata from Mon 17 Nov 2025 10:24:02 AM EST. 2025-11-22 07:51:55.493217 | controller | repo: downloading from remote: appstream 2025-11-22 07:51:55.493234 | controller | CentOS Stream 9 - AppStream 250 MB/s | 25 MB 00:00 2025-11-22 07:51:55.493251 | controller | appstream: using metadata from Mon 17 Nov 2025 10:27:35 AM EST. 2025-11-22 07:51:55.493269 | controller | repo: downloading from remote: crb 2025-11-22 07:51:55.493285 | controller | CentOS Stream 9 - CRB 160 MB/s | 7.3 MB 00:00 2025-11-22 07:51:55.493302 | controller | crb: using metadata from Mon 17 Nov 2025 10:32:16 AM EST. 2025-11-22 07:51:55.493318 | controller | repo: downloading from remote: extras-common 2025-11-22 07:51:55.493334 | controller | CentOS Stream 9 - Extras packages 227 kB/s | 20 kB 00:00 2025-11-22 07:51:55.493349 | controller | extras-common: using metadata from Thu 30 Oct 2025 09:20:08 AM EDT. 2025-11-22 07:51:55.493365 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-11-22 07:51:55.493381 | controller | Completion plugin: Generating completion cache... 2025-11-22 07:51:55.493398 | controller | Metadata cache created. 2025-11-22 07:51:55.493423 | controller | ok: Item: dnf makecache -v Runtime: 0:00:07.970275 2025-11-22 07:51:55.508085 | 2025-11-22 07:51:55.508137 | PLAY RECAP 2025-11-22 07:51:55.508180 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-11-22 07:51:55.508209 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-22 07:51:55.508229 | 2025-11-22 07:51:55.582282 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-11-22 07:51:55.583094 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-22 07:51:56.076776 | 2025-11-22 07:51:56.076867 | PLAY [all] 2025-11-22 07:51:56.096641 | 2025-11-22 07:51:56.096711 | TASK [Install binary dependencies] 2025-11-22 07:51:56.134924 | controller | ok 2025-11-22 07:51:56.152616 | 2025-11-22 07:51:56.152700 | TASK [bindep : Include find tasks] 2025-11-22 07:51:56.180760 | controller | ok 2025-11-22 07:51:56.187863 | controller | included: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-22 07:51:56.193526 | 2025-11-22 07:51:56.193594 | TASK [bindep : Look for bindep.txt] 2025-11-22 07:51:56.494942 | controller | ok 2025-11-22 07:51:56.501145 | 2025-11-22 07:51:56.501241 | TASK [bindep : Define bindep_file fact] 2025-11-22 07:51:56.529260 | controller | ok 2025-11-22 07:51:56.534208 | 2025-11-22 07:51:56.534281 | TASK [bindep : Look for other-requirements.txt] 2025-11-22 07:51:56.547398 | controller | skipping: Conditional result was False 2025-11-22 07:51:56.552828 | 2025-11-22 07:51:56.552902 | TASK [bindep : Define bindep_file fact] 2025-11-22 07:51:56.576481 | controller | skipping: Conditional result was False 2025-11-22 07:51:56.581928 | 2025-11-22 07:51:56.582009 | TASK [bindep : Look for bindep fallback file] 2025-11-22 07:51:56.605370 | controller | skipping: Conditional result was False 2025-11-22 07:51:56.610684 | 2025-11-22 07:51:56.610757 | TASK [bindep : Define bindep_file fact] 2025-11-22 07:51:56.634244 | controller | skipping: Conditional result was False 2025-11-22 07:51:56.639591 | 2025-11-22 07:51:56.639661 | TASK [bindep : Include bindep tasks] 2025-11-22 07:51:56.669035 | controller | ok 2025-11-22 07:51:56.675291 | controller | included: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-11-22 07:51:56.682731 | 2025-11-22 07:51:56.682801 | TASK [bindep : Look for bindep command] 2025-11-22 07:51:56.706204 | controller | skipping: Conditional result was False 2025-11-22 07:51:56.712030 | 2025-11-22 07:51:56.712099 | TASK [bindep : Check for system bindep] 2025-11-22 07:51:57.238059 | controller | ok: Runtime: 0:00:00.003831 2025-11-22 07:51:57.243383 | 2025-11-22 07:51:57.243448 | TASK [bindep : Define bindep_command fact] 2025-11-22 07:51:57.277014 | controller | skipping: Conditional result was False 2025-11-22 07:51:57.282318 | 2025-11-22 07:51:57.282384 | TASK [bindep : Include install tasks] 2025-11-22 07:51:57.309882 | controller | ok 2025-11-22 07:51:57.316210 | controller | included: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-11-22 07:51:57.324883 | 2025-11-22 07:51:57.324964 | TASK [bindep : Create temp dir for bindep] 2025-11-22 07:51:57.606021 | controller | changed 2025-11-22 07:51:57.612168 | 2025-11-22 07:51:57.612244 | TASK [Ensure we have pip dependencies] 2025-11-22 07:51:57.630330 | controller | ok 2025-11-22 07:51:57.653046 | 2025-11-22 07:51:57.653121 | TASK [ensure-pip : Check if pip is installed] 2025-11-22 02:51:57.852591 | controller | /usr/bin/pip3 2025-11-22 02:51:57.872201 | controller | /usr/bin/python3: No module named wheel 2025-11-22 07:51:58.175953 | controller | ok: Runtime: 0:00:00.026557 2025-11-22 07:51:58.181323 | 2025-11-22 07:51:58.181397 | LOOP [ensure-pip : Install pip from packages] 2025-11-22 07:51:58.208656 | controller | ok: "/var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-11-22 07:51:58.224789 | controller | included: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-11-22 07:51:58.246325 | 2025-11-22 07:51:58.246419 | TASK [ensure-pip : Install Python 3 pip] 2025-11-22 07:51:59.614276 | controller | changed 2025-11-22 07:51:59.619580 | 2025-11-22 07:51:59.619652 | TASK [ensure-pip : Check for EPEL repository] 2025-11-22 07:51:59.653043 | controller | skipping: Conditional result was False 2025-11-22 07:51:59.660045 | 2025-11-22 07:51:59.660125 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-11-22 07:51:59.693891 | controller | skipping: Conditional result was False 2025-11-22 07:51:59.699643 | 2025-11-22 07:51:59.699717 | TASK [ensure-pip : Install Python 2 pip] 2025-11-22 07:51:59.732945 | controller | skipping: Conditional result was False 2025-11-22 07:51:59.738574 | 2025-11-22 07:51:59.738674 | TASK [ensure-pip : Ensure setuptools] 2025-11-22 07:51:59.762275 | controller | skipping: Conditional result was False 2025-11-22 07:51:59.768012 | 2025-11-22 07:51:59.768089 | TASK [ensure-pip : Check for ensurepip module] 2025-11-22 07:52:00.295558 | controller | skipping: Conditional result was False 2025-11-22 07:52:00.301419 | 2025-11-22 07:52:00.301499 | TASK [ensure-pip : Ensure python3-venv] 2025-11-22 07:52:00.314927 | controller | skipping: Conditional result was False 2025-11-22 07:52:00.321127 | 2025-11-22 07:52:00.321204 | TASK [ensure-pip : Install pip from source] 2025-11-22 07:52:00.334158 | controller | skipping: Conditional result was False 2025-11-22 07:52:00.339559 | 2025-11-22 07:52:00.339633 | TASK [ensure-pip : Probe for venv python full path] 2025-11-22 02:52:00.536214 | controller | /usr/bin/python3 2025-11-22 07:52:00.864420 | controller | ok: Runtime: 0:00:00.004038 2025-11-22 07:52:00.870722 | 2025-11-22 07:52:00.870811 | TASK [ensure-pip : Set host default] 2025-11-22 07:52:00.929947 | controller | ok 2025-11-22 07:52:00.937030 | 2025-11-22 07:52:00.937119 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-11-22 07:52:00.985022 | controller | ok 2025-11-22 07:52:01.003868 | 2025-11-22 07:52:01.004470 | TASK [bindep : Install bindep into temporary venv] 2025-11-22 07:52:04.499732 | controller | changed 2025-11-22 07:52:04.504730 | 2025-11-22 07:52:04.504806 | TASK [bindep : Define bindep_command] 2025-11-22 07:52:04.522835 | controller | ok 2025-11-22 07:52:04.536267 | 2025-11-22 07:52:04.536342 | LOOP [bindep : Include package tasks] 2025-11-22 07:52:04.573405 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-11-22 07:52:04.573580 | controller | ok: All items complete 2025-11-22 07:52:04.573610 | 2025-11-22 07:52:04.586071 | controller | included: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-11-22 07:52:04.595684 | 2025-11-22 07:52:04.595751 | TASK [bindep : Define bindep_run fact] 2025-11-22 07:52:04.613153 | controller | ok 2025-11-22 07:52:04.617804 | 2025-11-22 07:52:04.617874 | TASK [bindep : Get list of packages to install from bindep] 2025-11-22 02:52:05.542273 | controller | podman 2025-11-22 02:52:05.568766 | controller | python3-jmespath 2025-11-22 02:52:05.568804 | controller | python3-libvirt 2025-11-22 02:52:05.568812 | controller | python3-lxml 2025-11-22 02:52:05.568818 | controller | python3-netaddr 2025-11-22 07:52:05.644280 | controller | ok: Runtime: 0:00:00.763905 2025-11-22 07:52:05.650173 | 2025-11-22 07:52:05.650243 | TASK [bindep : Install distro packages from bindep] 2025-11-22 07:52:50.502770 | controller | changed 2025-11-22 07:52:50.507842 | 2025-11-22 07:52:50.507932 | TASK [bindep : Check that packages are installed] 2025-11-22 07:52:51.532681 | controller | ok: Runtime: 0:00:00.721261 2025-11-22 07:52:51.538017 | 2025-11-22 07:52:51.538095 | TASK [bindep : Fail if we cannot install all packages] 2025-11-22 07:52:51.561639 | controller | skipping: Conditional result was False 2025-11-22 07:52:51.571538 | 2025-11-22 07:52:51.571603 | TASK [Run test-setup role] 2025-11-22 07:52:51.589437 | controller | ok 2025-11-22 07:52:51.605643 | 2025-11-22 07:52:51.605714 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-22 07:52:51.786054 | controller | ok 2025-11-22 07:52:51.791083 | 2025-11-22 07:52:51.791166 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-22 07:52:52.316964 | controller | skipping: Conditional result was False 2025-11-22 07:52:52.334841 | 2025-11-22 07:52:52.334934 | TASK [bindep : Remove bindep temp dir] 2025-11-22 07:52:52.626656 | controller | ok 2025-11-22 07:52:52.637087 | 2025-11-22 07:52:52.637148 | PLAY RECAP 2025-11-22 07:52:52.637193 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-11-22 07:52:52.637215 | 2025-11-22 07:52:52.704992 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-22 07:52:52.705861 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-11-22 07:52:53.204960 | 2025-11-22 07:52:53.205056 | PLAY [all] 2025-11-22 07:52:53.223328 | 2025-11-22 07:52:53.223404 | TASK [Abort when test_command variable is undefined] 2025-11-22 07:52:53.247307 | controller | skipping: Conditional result was False 2025-11-22 07:52:53.252590 | 2025-11-22 07:52:53.252670 | TASK [Convert test_command to list] 2025-11-22 07:52:53.286242 | controller | skipping: Conditional result was False 2025-11-22 07:52:53.292319 | 2025-11-22 07:52:53.292387 | TASK [Use test_command list] 2025-11-22 07:52:53.330525 | controller | ok 2025-11-22 07:52:53.335550 | 2025-11-22 07:52:53.335616 | LOOP [Run test_command] 2025-11-22 07:52:53.653852 | controller | no check to run 2025-11-22 07:52:53.654027 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.003699 2025-11-22 07:52:53.681008 | 2025-11-22 07:52:53.681098 | PLAY RECAP 2025-11-22 07:52:53.681142 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-11-22 07:52:53.681166 | 2025-11-22 07:52:53.746830 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-11-22 07:52:53.747813 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-22 07:52:54.241831 | 2025-11-22 07:52:54.241945 | PLAY [all] 2025-11-22 07:52:54.261557 | 2025-11-22 07:52:54.261630 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-22 07:52:54.513221 | controller | changed: non-zero return code 2025-11-22 07:52:54.518371 | 2025-11-22 07:52:54.518445 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-22 07:52:54.531859 | controller | skipping: Conditional result was False 2025-11-22 07:52:54.537133 | 2025-11-22 07:52:54.537202 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-22 07:52:54.556027 | 2025-11-22 07:52:54.556146 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-22 07:52:54.574874 | 2025-11-22 07:52:54.575026 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-22 07:52:54.588336 | controller | skipping: Conditional result was False 2025-11-22 07:52:54.593691 | 2025-11-22 07:52:54.593775 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-22 07:52:54.612043 | 2025-11-22 07:52:54.612164 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-22 07:52:54.625342 | controller | skipping: Conditional result was False 2025-11-22 07:52:54.631953 | 2025-11-22 07:52:54.632023 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-22 07:52:54.645080 | controller | skipping: Conditional result was False 2025-11-22 07:52:54.650390 | 2025-11-22 07:52:54.650454 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-22 07:52:54.663624 | controller | skipping: Conditional result was False 2025-11-22 07:52:54.685582 | 2025-11-22 07:52:54.685633 | PLAY RECAP 2025-11-22 07:52:54.685677 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-22 07:52:54.685699 | 2025-11-22 07:52:54.750506 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-22 07:52:54.751302 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-11-22 07:52:55.250522 | 2025-11-22 07:52:55.250624 | PLAY [all] 2025-11-22 07:52:55.268700 | 2025-11-22 07:52:55.268790 | TASK [include_role : fetch-output] 2025-11-22 07:52:55.297018 | controller | ok 2025-11-22 07:52:55.313058 | 2025-11-22 07:52:55.313137 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-22 07:52:55.356957 | controller | skipping: Conditional result was False 2025-11-22 07:52:55.362379 | 2025-11-22 07:52:55.362449 | TASK [fetch-output : Set log path for single node] 2025-11-22 07:52:55.390242 | controller | ok 2025-11-22 07:52:55.395075 | 2025-11-22 07:52:55.395146 | LOOP [fetch-output : Ensure local output dirs] 2025-11-22 07:52:55.719703 | controller -> localhost | ok: "/var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/work/logs" 2025-11-22 07:52:55.898357 | controller -> localhost | changed: "/var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/work/artifacts" 2025-11-22 07:52:56.077902 | controller -> localhost | changed: "/var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/work/docs" 2025-11-22 07:52:56.092986 | 2025-11-22 07:52:56.093083 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-22 07:52:56.598022 | controller | changed: .d..t...... ./ 2025-11-22 07:52:56.598215 | controller | changed: All items complete 2025-11-22 07:52:56.598244 | 2025-11-22 07:52:56.965373 | controller | changed: .d..t...... ./ 2025-11-22 07:52:57.324745 | controller | changed: .d..t...... ./ 2025-11-22 07:52:57.340295 | 2025-11-22 07:52:57.340400 | TASK [include_role : fetch-output-openshift] 2025-11-22 07:52:57.353613 | controller | skipping: Conditional result was False 2025-11-22 07:52:57.359204 | 2025-11-22 07:52:57.359275 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-22 07:52:57.689096 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.006878 2025-11-22 07:52:57.876803 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.006593 2025-11-22 07:52:57.902414 | 2025-11-22 07:52:57.902506 | PLAY [all] 2025-11-22 07:52:57.916180 | 2025-11-22 07:52:57.916253 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-11-22 07:52:58.268485 | controller | changed 2025-11-22 07:52:58.290047 | 2025-11-22 07:52:58.290101 | PLAY RECAP 2025-11-22 07:52:58.290145 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-11-22 07:52:58.290168 | 2025-11-22 07:52:58.355788 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-11-22 07:52:58.356665 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-11-22 07:52:58.893289 | 2025-11-22 07:52:58.893423 | PLAY [localhost] 2025-11-22 07:52:58.910723 | 2025-11-22 07:52:58.910803 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-22 07:52:59.211434 | localhost | changed 2025-11-22 07:52:59.215875 | 2025-11-22 07:52:59.215970 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-22 07:52:59.233348 | localhost | ok 2025-11-22 07:52:59.240900 | 2025-11-22 07:52:59.240996 | TASK [add-fileserver : Create SSH private key tempfile] 2025-11-22 07:52:59.531558 | localhost | changed 2025-11-22 07:52:59.536311 | 2025-11-22 07:52:59.536397 | TASK [add-fileserver : Create SSH private key from secret] 2025-11-22 07:53:00.080897 | localhost | changed 2025-11-22 07:53:00.085874 | 2025-11-22 07:53:00.085977 | TASK [add-fileserver : Add fileserver ssh key] 2025-11-22 07:53:00.447605 | localhost | Identity added: /var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/work/tmp/ansible.99yp_ij5 (/var/lib/zuul/builds/def40741e0c944638e59bf49ece32164/work/tmp/ansible.99yp_ij5) 2025-11-22 07:53:00.447808 | localhost | ok: Runtime: 0:00:00.006274 2025-11-22 07:53:00.451964 | 2025-11-22 07:53:00.452032 | TASK [add-fileserver : Remove SSH private key from disk] 2025-11-22 07:53:00.664147 | localhost | ok: Runtime: 0:00:00.004045 2025-11-22 07:53:00.668603 | 2025-11-22 07:53:00.668673 | TASK [add-fileserver : Add fileserver to inventory] 2025-11-22 07:53:00.715928 | localhost | changed 2025-11-22 07:53:00.719921 | 2025-11-22 07:53:00.719993 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-11-22 07:53:01.020737 | localhost | changed 2025-11-22 07:53:01.039248 | 2025-11-22 07:53:01.039312 | PLAY [localhost] 2025-11-22 07:53:01.050103 | 2025-11-22 07:53:01.050164 | TASK [Generate bulk log download script] 2025-11-22 07:53:01.066791 | localhost | ok 2025-11-22 07:53:01.078499 | 2025-11-22 07:53:01.078571 | TASK [local-log-download : Check API endpoint is defined] 2025-11-22 07:53:01.105277 | localhost | ok: All assertions passed 2025-11-22 07:53:01.109570 | 2025-11-22 07:53:01.109644 | TASK [local-log-download : Create download script] 2025-11-22 07:53:01.446225 | localhost -> localhost | changed 2025-11-22 07:53:01.454849 | 2025-11-22 07:53:01.454945 | TASK [Register quick-download link] 2025-11-22 07:53:01.471216 | localhost | ok 2025-11-22 07:53:01.504293 | 2025-11-22 07:53:01.504373 | PLAY [logserver.rdoproject.org] 2025-11-22 07:53:01.513326 | 2025-11-22 07:53:01.513386 | TASK [Set zuul-log-path fact] 2025-11-22 07:53:01.528453 | logserver.rdoproject.org | ok 2025-11-22 07:53:01.537019 | 2025-11-22 07:53:01.537085 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-22 07:53:01.552346 | logserver.rdoproject.org | ok 2025-11-22 07:53:01.557348 | 2025-11-22 07:53:01.557411 | TASK [upload-logs : Create log directories] 2025-11-22 07:53:03.254248 | logserver.rdoproject.org | changed 2025-11-22 07:53:03.258627 | 2025-11-22 07:53:03.258768 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-11-22 07:53:03.474202 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004606 2025-11-22 07:53:03.479195 | 2025-11-22 07:53:03.479278 | TASK [upload-logs : Upload logs to log server] 2025-11-22 07:53:04.810308 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-11-22 07:53:04.813083 | 2025-11-22 07:53:04.813156 | LOOP [upload-logs : Compress console log and json output] 2025-11-22 07:53:04.848446 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-22 07:53:04.856655 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-22 07:53:04.869753 | 2025-11-22 07:53:04.869846 | LOOP [upload-logs : Upload compressed console log and json output] 2025-11-22 07:53:04.902249 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-22 07:53:04.902465 | 2025-11-22 07:53:04.905840 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-22 07:53:04.916477 | 2025-11-22 07:53:04.916577 | LOOP [upload-logs : Upload console log and json output]