2025-10-02 16:45:38.885415 | Job console starting... 2025-10-02 16:45:38.901103 | Updating repositories 2025-10-02 16:45:38.941659 | Preparing job workspace 2025-10-02 16:45:42.940898 | Running Ansible setup... 2025-10-02 16:45:46.880146 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-02 16:45:47.506696 | 2025-10-02 16:45:47.506910 | PLAY [localhost] 2025-10-02 16:45:47.516035 | 2025-10-02 16:45:47.516135 | TASK [Gathering Facts] 2025-10-02 16:45:48.550653 | localhost | ok 2025-10-02 16:45:48.565390 | 2025-10-02 16:45:48.565547 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-02 16:45:48.972193 | localhost -> localhost | changed 2025-10-02 16:45:48.977692 | 2025-10-02 16:45:48.977832 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-02 16:45:49.811458 | localhost -> localhost | changed 2025-10-02 16:45:49.820922 | 2025-10-02 16:45:49.821009 | TASK [Setup log path fact] 2025-10-02 16:45:49.838880 | localhost | ok 2025-10-02 16:45:49.851559 | 2025-10-02 16:45:49.851668 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-02 16:45:49.880297 | localhost | ok 2025-10-02 16:45:49.889538 | 2025-10-02 16:45:49.889607 | TASK [emit-job-header : Print job information] 2025-10-02 16:45:49.927793 | # Job Information 2025-10-02 16:45:49.927957 | Ansible Version: 2.15.12 2025-10-02 16:45:49.927982 | Job: cifmw-molecule-cifmw_setup 2025-10-02 16:45:49.928001 | Pipeline: github-check 2025-10-02 16:45:49.928019 | Executor: ze03.softwarefactory-project.io 2025-10-02 16:45:49.928036 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3362 2025-10-02 16:45:49.928054 | Log URL (when completed): https://logserver.rdoproject.org/1b3/rdoproject.org/1b3f9b0e720545469d954d2a5cb2ea89/ 2025-10-02 16:45:49.928071 | Event ID: 0b5c9c70-9fae-11f0-9df5-29799d33dc04 2025-10-02 16:45:49.931601 | 2025-10-02 16:45:49.931662 | LOOP [emit-job-header : Print node information] 2025-10-02 16:45:50.033481 | localhost | ok: 2025-10-02 16:45:50.033674 | localhost | # Node Information 2025-10-02 16:45:50.033701 | localhost | Inventory Hostname: controller 2025-10-02 16:45:50.033726 | localhost | Hostname: np0005466885 2025-10-02 16:45:50.033763 | localhost | Username: zuul 2025-10-02 16:45:50.033785 | localhost | Distro: CentOS 9 2025-10-02 16:45:50.033802 | localhost | Provider: vexxhost-nodepool-tripleo 2025-10-02 16:45:50.033819 | localhost | Region: RegionOne 2025-10-02 16:45:50.033835 | localhost | Label: cloud-centos-9-stream-tripleo 2025-10-02 16:45:50.033851 | localhost | Product Name: OpenStack Nova 2025-10-02 16:45:50.033866 | localhost | Interface IP: 38.102.83.102 2025-10-02 16:45:50.078873 | 2025-10-02 16:45:50.079071 | PLAY [all] 2025-10-02 16:45:50.093693 | 2025-10-02 16:45:50.093864 | TASK [Gather network facts] 2025-10-02 16:45:50.601239 | controller | ok 2025-10-02 16:45:50.617786 | 2025-10-02 16:45:50.617899 | TASK [include_role : start-zuul-console] 2025-10-02 16:45:50.648986 | controller | ok 2025-10-02 16:45:50.661170 | 2025-10-02 16:45:50.661257 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-02 16:45:51.075503 | controller | ok 2025-10-02 16:45:51.096867 | 2025-10-02 16:45:51.097024 | TASK [include_role : add-build-sshkey] 2025-10-02 16:45:51.131699 | controller | ok 2025-10-02 16:45:51.151573 | 2025-10-02 16:45:51.151675 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-02 16:45:51.405983 | controller -> localhost | ok 2025-10-02 16:45:51.422362 | 2025-10-02 16:45:51.422538 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-02 16:45:51.455906 | controller | ok 2025-10-02 16:45:51.475251 | controller | included: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-02 16:45:51.483920 | 2025-10-02 16:45:51.484022 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-02 16:45:52.159707 | controller -> localhost | Generating public/private rsa key pair. 2025-10-02 16:45:52.160017 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/work/1b3f9b0e720545469d954d2a5cb2ea89_id_rsa. 2025-10-02 16:45:52.160061 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/work/1b3f9b0e720545469d954d2a5cb2ea89_id_rsa.pub. 2025-10-02 16:45:52.160095 | controller -> localhost | The key fingerprint is: 2025-10-02 16:45:52.160126 | controller -> localhost | SHA256:jcWBvyOPIHcQmdxPcxOuuYvIwRELGey2peE59PUcLdM zuul-build-sshkey 2025-10-02 16:45:52.160156 | controller -> localhost | The key's randomart image is: 2025-10-02 16:45:52.160185 | controller -> localhost | +---[RSA 3072]----+ 2025-10-02 16:45:52.160213 | controller -> localhost | | ... + .. .. | 2025-10-02 16:45:52.160242 | controller -> localhost | | .o= o.ooo | 2025-10-02 16:45:52.160270 | controller -> localhost | | .o .. +o=.. | 2025-10-02 16:45:52.160303 | controller -> localhost | | =.oo.+*oE | 2025-10-02 16:45:52.160362 | controller -> localhost | | + BooSo+= | 2025-10-02 16:45:52.160389 | controller -> localhost | | B.+.o =. | 2025-10-02 16:45:52.160414 | controller -> localhost | | +oo +.. | 2025-10-02 16:45:52.160442 | controller -> localhost | | . o.... | 2025-10-02 16:45:52.160467 | controller -> localhost | | o . . | 2025-10-02 16:45:52.160491 | controller -> localhost | +----[SHA256]-----+ 2025-10-02 16:45:52.160550 | controller -> localhost | ok: Runtime: 0:00:00.246693 2025-10-02 16:45:52.169269 | 2025-10-02 16:45:52.169402 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-02 16:45:52.193364 | controller | ok 2025-10-02 16:45:52.209840 | controller | included: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-02 16:45:52.225811 | 2025-10-02 16:45:52.225985 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-02 16:45:52.251774 | controller | skipping: Conditional result was False 2025-10-02 16:45:52.262042 | 2025-10-02 16:45:52.262199 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-02 16:45:52.727225 | controller | changed 2025-10-02 16:45:52.734837 | 2025-10-02 16:45:52.734987 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-02 16:45:53.013899 | controller | ok 2025-10-02 16:45:53.025389 | 2025-10-02 16:45:53.025595 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-02 16:45:53.898430 | controller | changed 2025-10-02 16:45:53.913917 | 2025-10-02 16:45:53.914146 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-02 16:45:54.856148 | controller | changed 2025-10-02 16:45:54.862957 | 2025-10-02 16:45:54.863052 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-02 16:45:54.889034 | controller | skipping: Conditional result was False 2025-10-02 16:45:54.896508 | 2025-10-02 16:45:54.896619 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-02 16:45:55.300480 | controller -> localhost | changed 2025-10-02 16:45:55.322902 | 2025-10-02 16:45:55.323098 | TASK [add-build-sshkey : Add back temp key] 2025-10-02 16:45:55.657385 | controller -> localhost | Identity added: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/work/1b3f9b0e720545469d954d2a5cb2ea89_id_rsa (zuul-build-sshkey) 2025-10-02 16:45:55.657601 | controller -> localhost | ok: Runtime: 0:00:00.008964 2025-10-02 16:45:55.664101 | 2025-10-02 16:45:55.664185 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-02 16:45:56.067934 | controller | ok 2025-10-02 16:45:56.076761 | 2025-10-02 16:45:56.076932 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-02 16:45:56.107791 | controller | skipping: Conditional result was False 2025-10-02 16:45:56.122436 | 2025-10-02 16:45:56.122582 | TASK [include_role : validate-host] 2025-10-02 16:45:56.143340 | controller | ok 2025-10-02 16:45:56.167653 | 2025-10-02 16:45:56.167824 | TASK [validate-host : Define zuul_info_dir fact] 2025-10-02 16:45:56.198907 | controller | ok 2025-10-02 16:45:56.204210 | 2025-10-02 16:45:56.204328 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-10-02 16:45:56.453854 | controller -> localhost | ok 2025-10-02 16:45:56.466110 | 2025-10-02 16:45:56.466319 | TASK [validate-host : Collect information about the host] 2025-10-02 16:45:57.258764 | controller | ok 2025-10-02 16:45:57.266966 | 2025-10-02 16:45:57.267030 | TASK [validate-host : Sanitize hostname] 2025-10-02 16:45:57.337748 | controller | ok 2025-10-02 16:45:57.343182 | 2025-10-02 16:45:57.343268 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-10-02 16:45:57.860721 | controller -> localhost | changed 2025-10-02 16:45:57.866760 | 2025-10-02 16:45:57.866856 | TASK [validate-host : Collect information about zuul worker] 2025-10-02 16:45:58.280488 | controller | ok 2025-10-02 16:45:58.292181 | 2025-10-02 16:45:58.292484 | TASK [validate-host : Write out all zuul information for each host] 2025-10-02 16:45:58.832516 | controller -> localhost | changed 2025-10-02 16:45:58.843624 | 2025-10-02 16:45:58.843753 | TASK [include_role : prepare-workspace-openshift] 2025-10-02 16:45:58.857349 | controller | skipping: Conditional result was False 2025-10-02 16:45:58.864261 | 2025-10-02 16:45:58.864479 | TASK [include_role : remove-zuul-sshkey] 2025-10-02 16:45:58.878750 | controller | skipping: Conditional result was False 2025-10-02 16:45:58.887955 | 2025-10-02 16:45:58.888071 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-02 16:45:59.181471 | controller | ok: "logs" 2025-10-02 16:45:59.181952 | controller | ok: All items complete 2025-10-02 16:45:59.182018 | 2025-10-02 16:45:59.385327 | controller | ok: "artifacts" 2025-10-02 16:45:59.600634 | controller | ok: "docs" 2025-10-02 16:45:59.620018 | 2025-10-02 16:45:59.620219 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-02 16:45:59.899662 | controller | changed: "logs" 2025-10-02 16:46:00.118581 | controller | changed: "artifacts" 2025-10-02 16:46:00.340821 | controller | changed: "docs" 2025-10-02 16:46:00.385187 | 2025-10-02 16:46:00.385297 | PLAY RECAP 2025-10-02 16:46:00.385355 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-02 16:46:00.385393 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-02 16:46:00.385418 | 2025-10-02 16:46:00.503018 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-02 16:46:00.504193 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-02 16:46:01.133095 | 2025-10-02 16:46:01.133255 | PLAY [localhost] 2025-10-02 16:46:01.152421 | 2025-10-02 16:46:01.152576 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-10-02 16:46:01.540023 | localhost | ok 2025-10-02 16:46:01.545782 | 2025-10-02 16:46:01.545884 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-10-02 16:46:02.232818 | localhost | changed 2025-10-02 16:46:02.253789 | 2025-10-02 16:46:02.253892 | PLAY [all] 2025-10-02 16:46:02.270458 | 2025-10-02 16:46:02.270533 | TASK [include_role : prepare-workspace] 2025-10-02 16:46:02.299844 | controller | ok 2025-10-02 16:46:02.314624 | 2025-10-02 16:46:02.314759 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-02 16:46:02.691117 | controller | ok 2025-10-02 16:46:02.705942 | 2025-10-02 16:46:02.706088 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-02 16:46:04.392623 | controller | Output suppressed because no_log was given 2025-10-02 16:46:04.413962 | 2025-10-02 16:46:04.414106 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-02 16:46:04.671149 | controller | changed: "logs" 2025-10-02 16:46:04.899878 | controller | changed: "artifacts" 2025-10-02 16:46:05.156825 | controller | changed: "docs" 2025-10-02 16:46:05.171385 | 2025-10-02 16:46:05.171544 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-02 16:46:05.470466 | controller | changed: "logs" 2025-10-02 16:46:05.470926 | controller | changed: All items complete 2025-10-02 16:46:05.470999 | 2025-10-02 16:46:05.705366 | controller | changed: "artifacts" 2025-10-02 16:46:05.945901 | controller | changed: "docs" 2025-10-02 16:46:05.975291 | 2025-10-02 16:46:05.975504 | TASK [Check if worker can sudo] 2025-10-02 16:46:06.526416 | controller | ok: Runtime: 0:00:00.050098 2025-10-02 16:46:06.539941 | 2025-10-02 16:46:06.540126 | TASK [configure-mirrors : Gather needed facts] 2025-10-02 16:46:06.598021 | controller | skipping: Conditional result was False 2025-10-02 16:46:06.611344 | 2025-10-02 16:46:06.611536 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-10-02 16:46:06.680175 | controller | ok 2025-10-02 16:46:06.697095 | controller | included: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-10-02 16:46:06.709922 | 2025-10-02 16:46:06.710065 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-10-02 16:46:07.058940 | controller | ok 2025-10-02 16:46:07.106952 | 2025-10-02 16:46:07.107094 | LOOP [configure-mirrors : Include OS-specific variables] 2025-10-02 16:46:07.169392 | controller | ok: "/var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-10-02 16:46:07.179849 | 2025-10-02 16:46:07.179971 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-10-02 16:46:08.084763 | controller | changed 2025-10-02 16:46:08.096908 | 2025-10-02 16:46:08.097065 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-10-02 16:46:08.185121 | controller | ok: "/var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-10-02 16:46:08.185290 | controller | ok: All items complete 2025-10-02 16:46:08.185318 | 2025-10-02 16:46:08.251564 | controller | included: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-10-02 16:46:08.261471 | 2025-10-02 16:46:08.261604 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-10-02 16:46:09.173658 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-10-02 16:46:10.054390 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-10-02 16:46:10.071426 | 2025-10-02 16:46:10.071578 | TASK [configure-mirrors : Disable deltrarpm] 2025-10-02 16:46:10.547291 | controller | changed: section and option added 2025-10-02 16:46:10.573761 | 2025-10-02 16:46:10.573908 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-10-02 16:46:11.489763 | controller | 29 files removed 2025-10-02 16:46:11.490162 | controller | ok: Item: dnf clean all Runtime: 0:00:00.575460 2025-10-02 16:46:11.490245 | controller | changed: All items complete 2025-10-02 16:46:11.490292 | 2025-10-02 16:46:22.318112 | 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-02 16:46:22.318277 | controller | DNF version: 4.14.0 2025-10-02 16:46:22.318333 | controller | cachedir: /var/cache/dnf 2025-10-02 16:46:22.318380 | controller | Making cache files for all metadata files. 2025-10-02 16:46:22.318424 | controller | baseos: has expired and will be refreshed. 2025-10-02 16:46:22.318464 | controller | appstream: has expired and will be refreshed. 2025-10-02 16:46:22.318502 | controller | crb: has expired and will be refreshed. 2025-10-02 16:46:22.318555 | controller | extras-common: has expired and will be refreshed. 2025-10-02 16:46:22.318618 | controller | repo: downloading from remote: baseos 2025-10-02 16:46:22.318665 | controller | CentOS Stream 9 - BaseOS 72 MB/s | 8.8 MB 00:00 2025-10-02 16:46:22.318704 | controller | baseos: using metadata from Tue 30 Sep 2025 01:12:56 PM EDT. 2025-10-02 16:46:22.318808 | controller | repo: downloading from remote: appstream 2025-10-02 16:46:22.318851 | controller | CentOS Stream 9 - AppStream 77 MB/s | 25 MB 00:00 2025-10-02 16:46:22.318900 | controller | appstream: using metadata from Tue 30 Sep 2025 01:16:29 PM EDT. 2025-10-02 16:46:22.318946 | controller | repo: downloading from remote: crb 2025-10-02 16:46:22.318991 | controller | CentOS Stream 9 - CRB 53 MB/s | 7.1 MB 00:00 2025-10-02 16:46:22.319137 | controller | crb: using metadata from Tue 30 Sep 2025 01:20:54 PM EDT. 2025-10-02 16:46:22.319189 | controller | repo: downloading from remote: extras-common 2025-10-02 16:46:22.319231 | controller | CentOS Stream 9 - Extras packages 1.0 MB/s | 20 kB 00:00 2025-10-02 16:46:22.319270 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-10-02 16:46:22.319308 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-10-02 16:46:22.319348 | controller | Completion plugin: Generating completion cache... 2025-10-02 16:46:22.319389 | controller | Metadata cache created. 2025-10-02 16:46:22.319445 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.554608 2025-10-02 16:46:22.340323 | 2025-10-02 16:46:22.340507 | PLAY RECAP 2025-10-02 16:46:22.340615 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-02 16:46:22.340690 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-02 16:46:22.340822 | 2025-10-02 16:46:22.477967 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-02 16:46:22.479403 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-02 16:46:23.072233 | 2025-10-02 16:46:23.072385 | PLAY [all] 2025-10-02 16:46:23.098804 | 2025-10-02 16:46:23.098951 | TASK [Install binary dependencies] 2025-10-02 16:46:23.148815 | controller | ok 2025-10-02 16:46:23.169177 | 2025-10-02 16:46:23.169336 | TASK [bindep : Include find tasks] 2025-10-02 16:46:23.199293 | controller | ok 2025-10-02 16:46:23.207531 | controller | included: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-02 16:46:23.214376 | 2025-10-02 16:46:23.214494 | TASK [bindep : Look for bindep.txt] 2025-10-02 16:46:23.611135 | controller | ok 2025-10-02 16:46:23.617890 | 2025-10-02 16:46:23.617971 | TASK [bindep : Define bindep_file fact] 2025-10-02 16:46:23.649242 | controller | ok 2025-10-02 16:46:23.656525 | 2025-10-02 16:46:23.656623 | TASK [bindep : Look for other-requirements.txt] 2025-10-02 16:46:23.680895 | controller | skipping: Conditional result was False 2025-10-02 16:46:23.686766 | 2025-10-02 16:46:23.686848 | TASK [bindep : Define bindep_file fact] 2025-10-02 16:46:23.720890 | controller | skipping: Conditional result was False 2025-10-02 16:46:23.729207 | 2025-10-02 16:46:23.729316 | TASK [bindep : Look for bindep fallback file] 2025-10-02 16:46:23.754247 | controller | skipping: Conditional result was False 2025-10-02 16:46:23.760994 | 2025-10-02 16:46:23.761132 | TASK [bindep : Define bindep_file fact] 2025-10-02 16:46:23.785503 | controller | skipping: Conditional result was False 2025-10-02 16:46:23.791810 | 2025-10-02 16:46:23.791891 | TASK [bindep : Include bindep tasks] 2025-10-02 16:46:23.822057 | controller | ok 2025-10-02 16:46:23.829052 | controller | included: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-10-02 16:46:23.837376 | 2025-10-02 16:46:23.837470 | TASK [bindep : Look for bindep command] 2025-10-02 16:46:23.861640 | controller | skipping: Conditional result was False 2025-10-02 16:46:23.868357 | 2025-10-02 16:46:23.868458 | TASK [bindep : Check for system bindep] 2025-10-02 16:46:24.398923 | controller | ok: Runtime: 0:00:00.007561 2025-10-02 16:46:24.412788 | 2025-10-02 16:46:24.413040 | TASK [bindep : Define bindep_command fact] 2025-10-02 16:46:24.440651 | controller | skipping: Conditional result was False 2025-10-02 16:46:24.454572 | 2025-10-02 16:46:24.454759 | TASK [bindep : Include install tasks] 2025-10-02 16:46:24.490157 | controller | ok 2025-10-02 16:46:24.500890 | controller | included: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-10-02 16:46:24.513333 | 2025-10-02 16:46:24.513425 | TASK [bindep : Create temp dir for bindep] 2025-10-02 16:46:24.880178 | controller | changed 2025-10-02 16:46:24.886577 | 2025-10-02 16:46:24.886667 | TASK [Ensure we have pip dependencies] 2025-10-02 16:46:24.911118 | controller | ok 2025-10-02 16:46:24.949388 | 2025-10-02 16:46:24.949530 | TASK [ensure-pip : Check if pip is installed] 2025-10-02 12:46:25.250904 | controller | /usr/bin/pip3 2025-10-02 12:46:25.273355 | controller | /usr/bin/python3: No module named wheel 2025-10-02 16:46:25.483066 | controller | ok: Runtime: 0:00:00.034734 2025-10-02 16:46:25.491106 | 2025-10-02 16:46:25.491194 | LOOP [ensure-pip : Install pip from packages] 2025-10-02 16:46:25.543294 | controller | ok: "/var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-10-02 16:46:25.556522 | controller | included: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-10-02 16:46:25.570994 | 2025-10-02 16:46:25.571093 | TASK [ensure-pip : Install Python 3 pip] 2025-10-02 16:46:28.242466 | controller | changed 2025-10-02 16:46:28.248006 | 2025-10-02 16:46:28.248112 | TASK [ensure-pip : Check for EPEL repository] 2025-10-02 16:46:28.283974 | controller | skipping: Conditional result was False 2025-10-02 16:46:28.300062 | 2025-10-02 16:46:28.300265 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-10-02 16:46:28.359217 | controller | skipping: Conditional result was False 2025-10-02 16:46:28.373000 | 2025-10-02 16:46:28.373295 | TASK [ensure-pip : Install Python 2 pip] 2025-10-02 16:46:28.431383 | controller | skipping: Conditional result was False 2025-10-02 16:46:28.445391 | 2025-10-02 16:46:28.445565 | TASK [ensure-pip : Ensure setuptools] 2025-10-02 16:46:28.462807 | controller | skipping: Conditional result was False 2025-10-02 16:46:28.476389 | 2025-10-02 16:46:28.476532 | TASK [ensure-pip : Check for ensurepip module] 2025-10-02 16:46:29.023416 | controller | skipping: Conditional result was False 2025-10-02 16:46:29.038238 | 2025-10-02 16:46:29.038451 | TASK [ensure-pip : Ensure python3-venv] 2025-10-02 16:46:29.056267 | controller | skipping: Conditional result was False 2025-10-02 16:46:29.069908 | 2025-10-02 16:46:29.070057 | TASK [ensure-pip : Install pip from source] 2025-10-02 16:46:29.087063 | controller | skipping: Conditional result was False 2025-10-02 16:46:29.100393 | 2025-10-02 16:46:29.100542 | TASK [ensure-pip : Probe for venv python full path] 2025-10-02 12:46:29.395346 | controller | /usr/bin/python3 2025-10-02 16:46:29.651922 | controller | ok: Runtime: 0:00:00.007772 2025-10-02 16:46:29.664243 | 2025-10-02 16:46:29.664425 | TASK [ensure-pip : Set host default] 2025-10-02 16:46:29.743652 | controller | ok 2025-10-02 16:46:29.755096 | 2025-10-02 16:46:29.755230 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-10-02 16:46:29.818820 | controller | ok 2025-10-02 16:46:29.828883 | 2025-10-02 16:46:29.828950 | TASK [bindep : Install bindep into temporary venv] 2025-10-02 16:46:34.107980 | controller | changed 2025-10-02 16:46:34.121396 | 2025-10-02 16:46:34.121512 | TASK [bindep : Define bindep_command] 2025-10-02 16:46:34.151809 | controller | ok 2025-10-02 16:46:34.157181 | 2025-10-02 16:46:34.157254 | LOOP [bindep : Include package tasks] 2025-10-02 16:46:34.226519 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-10-02 16:46:34.226671 | controller | ok: All items complete 2025-10-02 16:46:34.226698 | 2025-10-02 16:46:34.243677 | controller | included: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-10-02 16:46:34.255060 | 2025-10-02 16:46:34.255186 | TASK [bindep : Define bindep_run fact] 2025-10-02 16:46:34.284575 | controller | ok 2025-10-02 16:46:34.289708 | 2025-10-02 16:46:34.289805 | TASK [bindep : Get list of packages to install from bindep] 2025-10-02 12:46:35.563383 | controller | podman 2025-10-02 12:46:35.598611 | controller | python3-jmespath 2025-10-02 12:46:35.598741 | controller | python3-libvirt 2025-10-02 12:46:35.598751 | controller | python3-lxml 2025-10-02 12:46:35.598761 | controller | python3-netaddr 2025-10-02 16:46:35.823505 | controller | ok: Runtime: 0:00:01.065504 2025-10-02 16:46:35.831771 | 2025-10-02 16:46:35.831876 | TASK [bindep : Install distro packages from bindep] 2025-10-02 16:47:44.392391 | controller | changed 2025-10-02 16:47:44.405124 | 2025-10-02 16:47:44.405313 | TASK [bindep : Check that packages are installed] 2025-10-02 16:47:46.453412 | controller | ok: Runtime: 0:00:01.223255 2025-10-02 16:47:46.464504 | 2025-10-02 16:47:46.464611 | TASK [bindep : Fail if we cannot install all packages] 2025-10-02 16:47:46.502382 | controller | skipping: Conditional result was False 2025-10-02 16:47:46.516043 | 2025-10-02 16:47:46.516212 | TASK [Run test-setup role] 2025-10-02 16:47:46.542818 | controller | ok 2025-10-02 16:47:46.570017 | 2025-10-02 16:47:46.570190 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-02 16:47:46.863399 | controller | ok 2025-10-02 16:47:46.874823 | 2025-10-02 16:47:46.874975 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-02 16:47:47.424673 | controller | skipping: Conditional result was False 2025-10-02 16:47:47.470136 | 2025-10-02 16:47:47.470289 | TASK [bindep : Remove bindep temp dir] 2025-10-02 16:47:47.924371 | controller | ok 2025-10-02 16:47:47.940236 | 2025-10-02 16:47:47.940342 | PLAY RECAP 2025-10-02 16:47:47.940399 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-10-02 16:47:47.940428 | 2025-10-02 16:47:48.072690 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-02 16:47:48.075157 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-02 16:47:48.700299 | 2025-10-02 16:47:48.700418 | PLAY [all] 2025-10-02 16:47:48.720168 | 2025-10-02 16:47:48.720271 | TASK [Abort when test_command variable is undefined] 2025-10-02 16:47:48.744642 | controller | skipping: Conditional result was False 2025-10-02 16:47:48.750683 | 2025-10-02 16:47:48.750887 | TASK [Convert test_command to list] 2025-10-02 16:47:48.795320 | controller | skipping: Conditional result was False 2025-10-02 16:47:48.802179 | 2025-10-02 16:47:48.802246 | TASK [Use test_command list] 2025-10-02 16:47:48.872359 | controller | ok 2025-10-02 16:47:48.877859 | 2025-10-02 16:47:48.877922 | LOOP [Run test_command] 2025-10-02 16:47:49.334985 | controller | no check to run 2025-10-02 16:47:49.335235 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.009897 2025-10-02 16:47:49.360013 | 2025-10-02 16:47:49.360113 | PLAY RECAP 2025-10-02 16:47:49.360157 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-02 16:47:49.360182 | 2025-10-02 16:47:49.461701 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-02 16:47:49.463584 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-02 16:47:50.082699 | 2025-10-02 16:47:50.082842 | PLAY [all] 2025-10-02 16:47:50.103833 | 2025-10-02 16:47:50.103933 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-02 16:47:50.531580 | controller | changed: non-zero return code 2025-10-02 16:47:50.537325 | 2025-10-02 16:47:50.537415 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-02 16:47:50.562089 | controller | skipping: Conditional result was False 2025-10-02 16:47:50.568922 | 2025-10-02 16:47:50.569004 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-02 16:47:50.601316 | 2025-10-02 16:47:50.601473 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-02 16:47:50.642207 | 2025-10-02 16:47:50.642397 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-02 16:47:50.666889 | controller | skipping: Conditional result was False 2025-10-02 16:47:50.673279 | 2025-10-02 16:47:50.673354 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-02 16:47:50.705037 | 2025-10-02 16:47:50.705218 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-02 16:47:50.720276 | controller | skipping: Conditional result was False 2025-10-02 16:47:50.727164 | 2025-10-02 16:47:50.727266 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-02 16:47:50.742101 | controller | skipping: Conditional result was False 2025-10-02 16:47:50.748413 | 2025-10-02 16:47:50.748512 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-02 16:47:50.773083 | controller | skipping: Conditional result was False 2025-10-02 16:47:50.811437 | 2025-10-02 16:47:50.811559 | PLAY RECAP 2025-10-02 16:47:50.811632 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-02 16:47:50.811665 | 2025-10-02 16:47:50.911527 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-02 16:47:50.912691 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-02 16:47:51.519869 | 2025-10-02 16:47:51.519985 | PLAY [all] 2025-10-02 16:47:51.538950 | 2025-10-02 16:47:51.539043 | TASK [include_role : fetch-output] 2025-10-02 16:47:51.588997 | controller | ok 2025-10-02 16:47:51.606553 | 2025-10-02 16:47:51.606675 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-02 16:47:51.674243 | controller | skipping: Conditional result was False 2025-10-02 16:47:51.680688 | 2025-10-02 16:47:51.680873 | TASK [fetch-output : Set log path for single node] 2025-10-02 16:47:51.722518 | controller | ok 2025-10-02 16:47:51.728128 | 2025-10-02 16:47:51.728239 | LOOP [fetch-output : Ensure local output dirs] 2025-10-02 16:47:52.165913 | controller -> localhost | ok: "/var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/work/logs" 2025-10-02 16:47:52.462528 | controller -> localhost | changed: "/var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/work/artifacts" 2025-10-02 16:47:52.695841 | controller -> localhost | changed: "/var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/work/docs" 2025-10-02 16:47:52.712999 | 2025-10-02 16:47:52.713147 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-02 16:47:53.386862 | controller | changed: .d..t...... ./ 2025-10-02 16:47:53.387099 | controller | changed: All items complete 2025-10-02 16:47:53.387128 | 2025-10-02 16:47:53.898639 | controller | changed: .d..t...... ./ 2025-10-02 16:47:54.484662 | controller | changed: .d..t...... ./ 2025-10-02 16:47:54.517309 | 2025-10-02 16:47:54.517495 | TASK [include_role : fetch-output-openshift] 2025-10-02 16:47:54.560831 | controller | skipping: Conditional result was False 2025-10-02 16:47:54.571124 | 2025-10-02 16:47:54.571267 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-02 16:47:55.039933 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.013587 2025-10-02 16:47:55.316633 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.007985 2025-10-02 16:47:55.352242 | 2025-10-02 16:47:55.352379 | PLAY [all] 2025-10-02 16:47:55.367403 | 2025-10-02 16:47:55.367512 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-10-02 16:47:55.837181 | controller | changed 2025-10-02 16:47:55.862581 | 2025-10-02 16:47:55.862703 | PLAY RECAP 2025-10-02 16:47:55.862822 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-02 16:47:55.862861 | 2025-10-02 16:47:55.989900 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-02 16:47:55.991011 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-10-02 16:47:56.665551 | 2025-10-02 16:47:56.665681 | PLAY [localhost] 2025-10-02 16:47:56.685277 | 2025-10-02 16:47:56.685437 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-02 16:47:57.051887 | localhost | changed 2025-10-02 16:47:57.056591 | 2025-10-02 16:47:57.056676 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-02 16:47:57.085675 | localhost | ok 2025-10-02 16:47:57.095395 | 2025-10-02 16:47:57.095540 | TASK [add-fileserver : Create SSH private key tempfile] 2025-10-02 16:47:57.444931 | localhost | changed 2025-10-02 16:47:57.450006 | 2025-10-02 16:47:57.450097 | TASK [add-fileserver : Create SSH private key from secret] 2025-10-02 16:47:58.161949 | localhost | changed 2025-10-02 16:47:58.174108 | 2025-10-02 16:47:58.174261 | TASK [add-fileserver : Add fileserver ssh key] 2025-10-02 16:47:58.645393 | localhost | Identity added: /var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/work/tmp/ansible.5umowrab (/var/lib/zuul/builds/1b3f9b0e720545469d954d2a5cb2ea89/work/tmp/ansible.5umowrab) 2025-10-02 16:47:58.645581 | localhost | ok: Runtime: 0:00:00.013971 2025-10-02 16:47:58.650091 | 2025-10-02 16:47:58.650168 | TASK [add-fileserver : Remove SSH private key from disk] 2025-10-02 16:47:58.952956 | localhost | ok: Runtime: 0:00:00.010292 2025-10-02 16:47:58.958238 | 2025-10-02 16:47:58.958310 | TASK [add-fileserver : Add fileserver to inventory] 2025-10-02 16:47:59.041178 | localhost | changed 2025-10-02 16:47:59.047594 | 2025-10-02 16:47:59.047689 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-10-02 16:47:59.462450 | localhost | changed 2025-10-02 16:47:59.496754 | 2025-10-02 16:47:59.496857 | PLAY [localhost] 2025-10-02 16:47:59.516411 | 2025-10-02 16:47:59.516529 | TASK [Generate bulk log download script] 2025-10-02 16:47:59.536445 | localhost | ok 2025-10-02 16:47:59.552762 | 2025-10-02 16:47:59.552852 | TASK [local-log-download : Check API endpoint is defined] 2025-10-02 16:47:59.603819 | localhost | ok: All assertions passed 2025-10-02 16:47:59.610669 | 2025-10-02 16:47:59.610777 | TASK [local-log-download : Create download script] 2025-10-02 16:48:00.053941 | localhost -> localhost | changed 2025-10-02 16:48:00.074153 | 2025-10-02 16:48:00.074296 | TASK [Register quick-download link] 2025-10-02 16:48:00.109646 | localhost | ok 2025-10-02 16:48:00.184323 | 2025-10-02 16:48:00.184484 | PLAY [logserver.rdoproject.org] 2025-10-02 16:48:00.206516 | 2025-10-02 16:48:00.206680 | TASK [Set zuul-log-path fact] 2025-10-02 16:48:00.228386 | logserver.rdoproject.org | ok 2025-10-02 16:48:00.240643 | 2025-10-02 16:48:00.240760 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-02 16:48:00.281581 | logserver.rdoproject.org | ok 2025-10-02 16:48:00.293468 | 2025-10-02 16:48:00.293613 | TASK [upload-logs : Create log directories] 2025-10-02 16:48:00.981673 | logserver.rdoproject.org | changed 2025-10-02 16:48:00.988324 | 2025-10-02 16:48:00.988451 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-10-02 16:48:01.246649 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.005532 2025-10-02 16:48:01.251459 | 2025-10-02 16:48:01.251525 | TASK [upload-logs : Upload logs to log server] 2025-10-02 16:48:01.930469 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-10-02 16:48:01.933484 | 2025-10-02 16:48:01.933547 | LOOP [upload-logs : Compress console log and json output] 2025-10-02 16:48:01.995467 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 16:48:02.005072 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 16:48:02.013810 | 2025-10-02 16:48:02.013935 | LOOP [upload-logs : Upload compressed console log and json output] 2025-10-02 16:48:02.054386 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 16:48:02.054700 | 2025-10-02 16:48:02.058265 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 16:48:02.063833 | 2025-10-02 16:48:02.063949 | LOOP [upload-logs : Upload console log and json output]