2025-10-02 15:08:45.353350 | Job console starting... 2025-10-02 15:08:45.373562 | Updating repositories 2025-10-02 15:08:45.406382 | Preparing job workspace 2025-10-02 15:08:48.795863 | Running Ansible setup... 2025-10-02 15:08:52.784298 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-02 15:08:53.398574 | 2025-10-02 15:08:53.398699 | PLAY [localhost] 2025-10-02 15:08:53.406995 | 2025-10-02 15:08:53.407064 | TASK [Gathering Facts] 2025-10-02 15:08:54.376867 | localhost | ok 2025-10-02 15:08:54.390740 | 2025-10-02 15:08:54.390835 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-02 15:08:54.772285 | localhost -> localhost | changed 2025-10-02 15:08:54.778055 | 2025-10-02 15:08:54.778125 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-02 15:08:55.643446 | localhost -> localhost | changed 2025-10-02 15:08:55.652553 | 2025-10-02 15:08:55.652719 | TASK [Setup log path fact] 2025-10-02 15:08:55.674942 | localhost | ok 2025-10-02 15:08:55.690101 | 2025-10-02 15:08:55.690172 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-02 15:08:55.717780 | localhost | ok 2025-10-02 15:08:55.725961 | 2025-10-02 15:08:55.726037 | TASK [emit-job-header : Print job information] 2025-10-02 15:08:55.752898 | # Job Information 2025-10-02 15:08:55.753044 | Ansible Version: 2.15.12 2025-10-02 15:08:55.753069 | Job: cifmw-molecule-cifmw_helpers 2025-10-02 15:08:55.753089 | Pipeline: github-check 2025-10-02 15:08:55.753107 | Executor: ze04.softwarefactory-project.io 2025-10-02 15:08:55.753124 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3362 2025-10-02 15:08:55.753143 | Log URL (when completed): https://logserver.rdoproject.org/a28/rdoproject.org/a28251c91f864e81a17e2e43180bdbd5/ 2025-10-02 15:08:55.753160 | Event ID: 854a5e80-9fa1-11f0-891b-738b4b5da685 2025-10-02 15:08:55.757051 | 2025-10-02 15:08:55.757114 | LOOP [emit-job-header : Print node information] 2025-10-02 15:08:55.852943 | localhost | ok: 2025-10-02 15:08:55.853142 | localhost | # Node Information 2025-10-02 15:08:55.853170 | localhost | Inventory Hostname: controller 2025-10-02 15:08:55.853193 | localhost | Hostname: np0005466495 2025-10-02 15:08:55.853225 | localhost | Username: zuul 2025-10-02 15:08:55.853248 | localhost | Distro: CentOS 9 2025-10-02 15:08:55.853267 | localhost | Provider: vexxhost-nodepool-tripleo 2025-10-02 15:08:55.853284 | localhost | Region: RegionOne 2025-10-02 15:08:55.853301 | localhost | Label: cloud-centos-9-stream-tripleo 2025-10-02 15:08:55.853318 | localhost | Product Name: OpenStack Nova 2025-10-02 15:08:55.853335 | localhost | Interface IP: 38.129.56.155 2025-10-02 15:08:55.877039 | 2025-10-02 15:08:55.877105 | PLAY [all] 2025-10-02 15:08:55.883455 | 2025-10-02 15:08:55.883519 | TASK [Gather network facts] 2025-10-02 15:08:56.359403 | controller | ok 2025-10-02 15:08:56.392085 | 2025-10-02 15:08:56.392191 | TASK [include_role : start-zuul-console] 2025-10-02 15:08:56.445990 | controller | ok 2025-10-02 15:08:56.473528 | 2025-10-02 15:08:56.473640 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-02 15:08:56.921153 | controller | ok 2025-10-02 15:08:56.945629 | 2025-10-02 15:08:56.945739 | TASK [include_role : add-build-sshkey] 2025-10-02 15:08:56.964529 | controller | ok 2025-10-02 15:08:56.983002 | 2025-10-02 15:08:56.983084 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-02 15:08:57.209271 | controller -> localhost | ok 2025-10-02 15:08:57.215115 | 2025-10-02 15:08:57.215178 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-02 15:08:57.243973 | controller | ok 2025-10-02 15:08:57.267097 | controller | included: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-02 15:08:57.272758 | 2025-10-02 15:08:57.272819 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-02 15:08:57.970972 | controller -> localhost | Generating public/private rsa key pair. 2025-10-02 15:08:57.971160 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/work/a28251c91f864e81a17e2e43180bdbd5_id_rsa. 2025-10-02 15:08:57.971209 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/work/a28251c91f864e81a17e2e43180bdbd5_id_rsa.pub. 2025-10-02 15:08:57.971232 | controller -> localhost | The key fingerprint is: 2025-10-02 15:08:57.971254 | controller -> localhost | SHA256:s8DvPPytxYMs1Khjc3KPdcyjrT8YjyfKI+VtU+rbNp8 zuul-build-sshkey 2025-10-02 15:08:57.971274 | controller -> localhost | The key's randomart image is: 2025-10-02 15:08:57.971294 | controller -> localhost | +---[RSA 3072]----+ 2025-10-02 15:08:57.971312 | controller -> localhost | | | 2025-10-02 15:08:57.971331 | controller -> localhost | | | 2025-10-02 15:08:57.971349 | controller -> localhost | | | 2025-10-02 15:08:57.971367 | controller -> localhost | | . o | 2025-10-02 15:08:57.971386 | controller -> localhost | | o S . | 2025-10-02 15:08:57.971404 | controller -> localhost | | =.+.=. | 2025-10-02 15:08:57.971422 | controller -> localhost | | *+*.+BO | 2025-10-02 15:08:57.971440 | controller -> localhost | | ..X==OB*o . | 2025-10-02 15:08:57.971459 | controller -> localhost | | .*BOX=+E | 2025-10-02 15:08:57.971477 | controller -> localhost | +----[SHA256]-----+ 2025-10-02 15:08:57.971521 | controller -> localhost | ok: Runtime: 0:00:00.108035 2025-10-02 15:08:57.977469 | 2025-10-02 15:08:57.977605 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-02 15:08:58.000747 | controller | ok 2025-10-02 15:08:58.011982 | controller | included: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-02 15:08:58.020565 | 2025-10-02 15:08:58.020634 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-02 15:08:58.044925 | controller | skipping: Conditional result was False 2025-10-02 15:08:58.050986 | 2025-10-02 15:08:58.051056 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-02 15:08:58.636618 | controller | changed 2025-10-02 15:08:58.645549 | 2025-10-02 15:08:58.645622 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-02 15:08:58.923461 | controller | ok 2025-10-02 15:08:58.934251 | 2025-10-02 15:08:58.934493 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-02 15:08:59.825865 | controller | changed 2025-10-02 15:08:59.833186 | 2025-10-02 15:08:59.833275 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-02 15:09:00.600618 | controller | changed 2025-10-02 15:09:00.611817 | 2025-10-02 15:09:00.611951 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-02 15:09:00.635984 | controller | skipping: Conditional result was False 2025-10-02 15:09:00.641395 | 2025-10-02 15:09:00.641458 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-02 15:09:01.011908 | controller -> localhost | changed 2025-10-02 15:09:01.030004 | 2025-10-02 15:09:01.030104 | TASK [add-build-sshkey : Add back temp key] 2025-10-02 15:09:01.266253 | controller -> localhost | Identity added: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/work/a28251c91f864e81a17e2e43180bdbd5_id_rsa (zuul-build-sshkey) 2025-10-02 15:09:01.266433 | controller -> localhost | ok: Runtime: 0:00:00.007679 2025-10-02 15:09:01.272147 | 2025-10-02 15:09:01.272204 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-02 15:09:01.635655 | controller | ok 2025-10-02 15:09:01.641082 | 2025-10-02 15:09:01.641147 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-02 15:09:01.675235 | controller | skipping: Conditional result was False 2025-10-02 15:09:01.687378 | 2025-10-02 15:09:01.687455 | TASK [include_role : validate-host] 2025-10-02 15:09:01.749484 | controller | ok 2025-10-02 15:09:01.779895 | 2025-10-02 15:09:01.780013 | TASK [validate-host : Define zuul_info_dir fact] 2025-10-02 15:09:01.852246 | controller | ok 2025-10-02 15:09:01.860426 | 2025-10-02 15:09:01.860539 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-10-02 15:09:02.171356 | controller -> localhost | ok 2025-10-02 15:09:02.177411 | 2025-10-02 15:09:02.177473 | TASK [validate-host : Collect information about the host] 2025-10-02 15:09:02.992792 | controller | ok 2025-10-02 15:09:03.009469 | 2025-10-02 15:09:03.009547 | TASK [validate-host : Sanitize hostname] 2025-10-02 15:09:03.108841 | controller | ok 2025-10-02 15:09:03.113923 | 2025-10-02 15:09:03.113988 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-10-02 15:09:03.727446 | controller -> localhost | changed 2025-10-02 15:09:03.733379 | 2025-10-02 15:09:03.733442 | TASK [validate-host : Collect information about zuul worker] 2025-10-02 15:09:04.137571 | controller | ok 2025-10-02 15:09:04.143913 | 2025-10-02 15:09:04.144005 | TASK [validate-host : Write out all zuul information for each host] 2025-10-02 15:09:04.762981 | controller -> localhost | changed 2025-10-02 15:09:04.774024 | 2025-10-02 15:09:04.774127 | TASK [include_role : prepare-workspace-openshift] 2025-10-02 15:09:04.787933 | controller | skipping: Conditional result was False 2025-10-02 15:09:04.793135 | 2025-10-02 15:09:04.793195 | TASK [include_role : remove-zuul-sshkey] 2025-10-02 15:09:04.806819 | controller | skipping: Conditional result was False 2025-10-02 15:09:04.812709 | 2025-10-02 15:09:04.812775 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-02 15:09:05.070650 | controller | ok: "logs" 2025-10-02 15:09:05.072148 | controller | ok: All items complete 2025-10-02 15:09:05.072196 | 2025-10-02 15:09:05.287191 | controller | ok: "artifacts" 2025-10-02 15:09:05.522437 | controller | ok: "docs" 2025-10-02 15:09:05.532623 | 2025-10-02 15:09:05.532775 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-02 15:09:05.834455 | controller | changed: "logs" 2025-10-02 15:09:06.048280 | controller | changed: "artifacts" 2025-10-02 15:09:06.294618 | controller | changed: "docs" 2025-10-02 15:09:06.326545 | 2025-10-02 15:09:06.326603 | PLAY RECAP 2025-10-02 15:09:06.326649 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-02 15:09:06.326719 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-02 15:09:06.326749 | 2025-10-02 15:09:06.445343 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-02 15:09:06.446166 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-02 15:09:07.125498 | 2025-10-02 15:09:07.125611 | PLAY [localhost] 2025-10-02 15:09:07.142704 | 2025-10-02 15:09:07.142781 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-10-02 15:09:07.585935 | localhost | ok 2025-10-02 15:09:07.591346 | 2025-10-02 15:09:07.591466 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-10-02 15:09:08.214063 | localhost | changed 2025-10-02 15:09:08.234133 | 2025-10-02 15:09:08.234257 | PLAY [all] 2025-10-02 15:09:08.249651 | 2025-10-02 15:09:08.249731 | TASK [include_role : prepare-workspace] 2025-10-02 15:09:08.268668 | controller | ok 2025-10-02 15:09:08.285772 | 2025-10-02 15:09:08.285850 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-02 15:09:08.813574 | controller | ok 2025-10-02 15:09:08.826956 | 2025-10-02 15:09:08.827045 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-02 15:09:10.544616 | controller | Output suppressed because no_log was given 2025-10-02 15:09:10.558999 | 2025-10-02 15:09:10.559077 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-02 15:09:10.792485 | controller | changed: "logs" 2025-10-02 15:09:10.983500 | controller | changed: "artifacts" 2025-10-02 15:09:11.198480 | controller | changed: "docs" 2025-10-02 15:09:11.223469 | 2025-10-02 15:09:11.223663 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-02 15:09:11.467449 | controller | changed: "logs" 2025-10-02 15:09:11.467661 | controller | changed: All items complete 2025-10-02 15:09:11.469952 | 2025-10-02 15:09:11.675947 | controller | changed: "artifacts" 2025-10-02 15:09:11.908649 | controller | changed: "docs" 2025-10-02 15:09:11.923260 | 2025-10-02 15:09:11.923381 | TASK [Check if worker can sudo] 2025-10-02 15:09:12.975134 | controller | ok: Runtime: 0:00:00.165238 2025-10-02 15:09:12.987315 | 2025-10-02 15:09:12.987452 | TASK [configure-mirrors : Gather needed facts] 2025-10-02 15:09:13.055643 | controller | skipping: Conditional result was False 2025-10-02 15:09:13.062356 | 2025-10-02 15:09:13.062425 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-10-02 15:09:13.121355 | controller | ok 2025-10-02 15:09:13.129349 | controller | included: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-10-02 15:09:13.134973 | 2025-10-02 15:09:13.135037 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-10-02 15:09:13.470071 | controller | ok 2025-10-02 15:09:13.477865 | 2025-10-02 15:09:13.477950 | LOOP [configure-mirrors : Include OS-specific variables] 2025-10-02 15:09:13.541780 | controller | ok: "/var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-10-02 15:09:13.550259 | 2025-10-02 15:09:13.550374 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-10-02 15:09:14.470673 | controller | changed 2025-10-02 15:09:14.477637 | 2025-10-02 15:09:14.477748 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-10-02 15:09:14.546004 | controller | ok: "/var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-10-02 15:09:14.546210 | controller | ok: All items complete 2025-10-02 15:09:14.546238 | 2025-10-02 15:09:14.606903 | controller | included: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-10-02 15:09:14.613283 | 2025-10-02 15:09:14.613353 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-10-02 15:09:15.467411 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-10-02 15:09:16.209108 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-10-02 15:09:16.221273 | 2025-10-02 15:09:16.221422 | TASK [configure-mirrors : Disable deltrarpm] 2025-10-02 15:09:16.696327 | controller | changed: section and option added 2025-10-02 15:09:16.735048 | 2025-10-02 15:09:16.735148 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-10-02 15:09:18.271315 | controller | 29 files removed 2025-10-02 15:09:18.271578 | controller | ok: Item: dnf clean all Runtime: 0:00:01.204883 2025-10-02 15:09:18.271632 | controller | changed: All items complete 2025-10-02 15:09:18.271661 | 2025-10-02 15:09:29.986321 | 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 15:09:29.986421 | controller | DNF version: 4.14.0 2025-10-02 15:09:29.986446 | controller | cachedir: /var/cache/dnf 2025-10-02 15:09:29.986467 | controller | Making cache files for all metadata files. 2025-10-02 15:09:29.986487 | controller | baseos: has expired and will be refreshed. 2025-10-02 15:09:29.986504 | controller | appstream: has expired and will be refreshed. 2025-10-02 15:09:29.986522 | controller | crb: has expired and will be refreshed. 2025-10-02 15:09:29.986548 | controller | extras-common: has expired and will be refreshed. 2025-10-02 15:09:29.986566 | controller | repo: downloading from remote: baseos 2025-10-02 15:09:29.986584 | controller | CentOS Stream 9 - BaseOS 21 MB/s | 8.8 MB 00:00 2025-10-02 15:09:29.986601 | controller | baseos: using metadata from Tue 30 Sep 2025 01:12:56 PM EDT. 2025-10-02 15:09:29.986618 | controller | repo: downloading from remote: appstream 2025-10-02 15:09:29.986635 | controller | CentOS Stream 9 - AppStream 52 MB/s | 25 MB 00:00 2025-10-02 15:09:29.986652 | controller | appstream: using metadata from Tue 30 Sep 2025 01:16:29 PM EDT. 2025-10-02 15:09:29.986669 | controller | repo: downloading from remote: crb 2025-10-02 15:09:29.986816 | controller | CentOS Stream 9 - CRB 58 MB/s | 7.1 MB 00:00 2025-10-02 15:09:29.986840 | controller | crb: using metadata from Tue 30 Sep 2025 01:20:54 PM EDT. 2025-10-02 15:09:29.986859 | controller | repo: downloading from remote: extras-common 2025-10-02 15:09:29.986877 | controller | CentOS Stream 9 - Extras packages 717 kB/s | 20 kB 00:00 2025-10-02 15:09:29.986894 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-10-02 15:09:29.986911 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-10-02 15:09:29.986928 | controller | Completion plugin: Generating completion cache... 2025-10-02 15:09:29.986945 | controller | Metadata cache created. 2025-10-02 15:09:29.986971 | controller | ok: Item: dnf makecache -v Runtime: 0:00:11.445730 2025-10-02 15:09:30.001041 | 2025-10-02 15:09:30.001139 | PLAY RECAP 2025-10-02 15:09:30.001181 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-02 15:09:30.001207 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-02 15:09:30.001225 | 2025-10-02 15:09:30.112452 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-02 15:09:30.113394 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-02 15:09:30.710457 | 2025-10-02 15:09:30.710562 | PLAY [all] 2025-10-02 15:09:30.733442 | 2025-10-02 15:09:30.733531 | TASK [Install binary dependencies] 2025-10-02 15:09:30.803245 | controller | ok 2025-10-02 15:09:30.823492 | 2025-10-02 15:09:30.823575 | TASK [bindep : Include find tasks] 2025-10-02 15:09:30.855800 | controller | ok 2025-10-02 15:09:30.863575 | controller | included: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-02 15:09:30.869572 | 2025-10-02 15:09:30.869637 | TASK [bindep : Look for bindep.txt] 2025-10-02 15:09:31.253802 | controller | ok 2025-10-02 15:09:31.260794 | 2025-10-02 15:09:31.260866 | TASK [bindep : Define bindep_file fact] 2025-10-02 15:09:31.290499 | controller | ok 2025-10-02 15:09:31.297054 | 2025-10-02 15:09:31.297138 | TASK [bindep : Look for other-requirements.txt] 2025-10-02 15:09:31.312799 | controller | skipping: Conditional result was False 2025-10-02 15:09:31.319640 | 2025-10-02 15:09:31.319751 | TASK [bindep : Define bindep_file fact] 2025-10-02 15:09:31.347071 | controller | skipping: Conditional result was False 2025-10-02 15:09:31.352723 | 2025-10-02 15:09:31.352788 | TASK [bindep : Look for bindep fallback file] 2025-10-02 15:09:31.376162 | controller | skipping: Conditional result was False 2025-10-02 15:09:31.381822 | 2025-10-02 15:09:31.381891 | TASK [bindep : Define bindep_file fact] 2025-10-02 15:09:31.405109 | controller | skipping: Conditional result was False 2025-10-02 15:09:31.410639 | 2025-10-02 15:09:31.410717 | TASK [bindep : Include bindep tasks] 2025-10-02 15:09:31.440841 | controller | ok 2025-10-02 15:09:31.448074 | controller | included: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-10-02 15:09:31.455937 | 2025-10-02 15:09:31.456003 | TASK [bindep : Look for bindep command] 2025-10-02 15:09:31.479694 | controller | skipping: Conditional result was False 2025-10-02 15:09:31.486172 | 2025-10-02 15:09:31.486237 | TASK [bindep : Check for system bindep] 2025-10-02 15:09:32.023083 | controller | ok: Runtime: 0:00:00.006881 2025-10-02 15:09:32.029082 | 2025-10-02 15:09:32.029182 | TASK [bindep : Define bindep_command fact] 2025-10-02 15:09:32.053306 | controller | skipping: Conditional result was False 2025-10-02 15:09:32.059654 | 2025-10-02 15:09:32.059765 | TASK [bindep : Include install tasks] 2025-10-02 15:09:32.098954 | controller | ok 2025-10-02 15:09:32.106369 | controller | included: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-10-02 15:09:32.116875 | 2025-10-02 15:09:32.116951 | TASK [bindep : Create temp dir for bindep] 2025-10-02 15:09:32.518025 | controller | changed 2025-10-02 15:09:32.523235 | 2025-10-02 15:09:32.523293 | TASK [Ensure we have pip dependencies] 2025-10-02 15:09:32.542373 | controller | ok 2025-10-02 15:09:32.566265 | 2025-10-02 15:09:32.566393 | TASK [ensure-pip : Check if pip is installed] 2025-10-02 11:09:32.897148 | controller | /usr/bin/pip3 2025-10-02 11:09:32.919225 | controller | /usr/bin/python3: No module named wheel 2025-10-02 15:09:33.094055 | controller | ok: Runtime: 0:00:00.033679 2025-10-02 15:09:33.100527 | 2025-10-02 15:09:33.100605 | LOOP [ensure-pip : Install pip from packages] 2025-10-02 15:09:33.133201 | controller | ok: "/var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-10-02 15:09:33.144395 | controller | included: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-10-02 15:09:33.155752 | 2025-10-02 15:09:33.155822 | TASK [ensure-pip : Install Python 3 pip] 2025-10-02 15:09:35.562338 | controller | changed 2025-10-02 15:09:35.573776 | 2025-10-02 15:09:35.573885 | TASK [ensure-pip : Check for EPEL repository] 2025-10-02 15:09:35.619246 | controller | skipping: Conditional result was False 2025-10-02 15:09:35.627706 | 2025-10-02 15:09:35.627796 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-10-02 15:09:35.693643 | controller | skipping: Conditional result was False 2025-10-02 15:09:35.700845 | 2025-10-02 15:09:35.700924 | TASK [ensure-pip : Install Python 2 pip] 2025-10-02 15:09:35.738845 | controller | skipping: Conditional result was False 2025-10-02 15:09:35.749598 | 2025-10-02 15:09:35.749752 | TASK [ensure-pip : Ensure setuptools] 2025-10-02 15:09:35.775261 | controller | skipping: Conditional result was False 2025-10-02 15:09:35.784421 | 2025-10-02 15:09:35.784520 | TASK [ensure-pip : Check for ensurepip module] 2025-10-02 15:09:36.339138 | controller | skipping: Conditional result was False 2025-10-02 15:09:36.348245 | 2025-10-02 15:09:36.348341 | TASK [ensure-pip : Ensure python3-venv] 2025-10-02 15:09:36.373224 | controller | skipping: Conditional result was False 2025-10-02 15:09:36.381461 | 2025-10-02 15:09:36.381544 | TASK [ensure-pip : Install pip from source] 2025-10-02 15:09:36.406446 | controller | skipping: Conditional result was False 2025-10-02 15:09:36.414132 | 2025-10-02 15:09:36.414215 | TASK [ensure-pip : Probe for venv python full path] 2025-10-02 11:09:36.755977 | controller | /usr/bin/python3 2025-10-02 15:09:36.954824 | controller | ok: Runtime: 0:00:00.009421 2025-10-02 15:09:36.962767 | 2025-10-02 15:09:36.962860 | TASK [ensure-pip : Set host default] 2025-10-02 15:09:37.043337 | controller | ok 2025-10-02 15:09:37.056015 | 2025-10-02 15:09:37.056207 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-10-02 15:09:37.134745 | controller | ok 2025-10-02 15:09:37.148582 | 2025-10-02 15:09:37.148695 | TASK [bindep : Install bindep into temporary venv] 2025-10-02 15:09:41.620163 | controller | changed 2025-10-02 15:09:41.634773 | 2025-10-02 15:09:41.635018 | TASK [bindep : Define bindep_command] 2025-10-02 15:09:41.684463 | controller | ok 2025-10-02 15:09:41.700513 | 2025-10-02 15:09:41.700674 | LOOP [bindep : Include package tasks] 2025-10-02 15:09:41.780866 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-10-02 15:09:41.781100 | controller | ok: All items complete 2025-10-02 15:09:41.781127 | 2025-10-02 15:09:41.810633 | controller | included: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-10-02 15:09:41.825734 | 2025-10-02 15:09:41.825847 | TASK [bindep : Define bindep_run fact] 2025-10-02 15:09:41.859550 | controller | ok 2025-10-02 15:09:41.867077 | 2025-10-02 15:09:41.867170 | TASK [bindep : Get list of packages to install from bindep] 2025-10-02 11:09:43.337198 | controller | podman 2025-10-02 11:09:43.386003 | controller | python3-jmespath 2025-10-02 11:09:43.386163 | controller | python3-libvirt 2025-10-02 11:09:43.386172 | controller | python3-lxml 2025-10-02 11:09:43.386182 | controller | python3-netaddr 2025-10-02 15:09:43.418326 | controller | ok: Runtime: 0:00:01.241137 2025-10-02 15:09:43.423792 | 2025-10-02 15:09:43.423949 | TASK [bindep : Install distro packages from bindep] 2025-10-02 15:11:02.555038 | controller | changed 2025-10-02 15:11:02.561029 | 2025-10-02 15:11:02.561089 | TASK [bindep : Check that packages are installed] 2025-10-02 15:11:04.139328 | controller | ok: Runtime: 0:00:01.210963 2025-10-02 15:11:04.155411 | 2025-10-02 15:11:04.155539 | TASK [bindep : Fail if we cannot install all packages] 2025-10-02 15:11:04.189969 | controller | skipping: Conditional result was False 2025-10-02 15:11:04.201414 | 2025-10-02 15:11:04.201517 | TASK [Run test-setup role] 2025-10-02 15:11:04.221235 | controller | ok 2025-10-02 15:11:04.258793 | 2025-10-02 15:11:04.258915 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-02 15:11:04.495402 | controller | ok 2025-10-02 15:11:04.509243 | 2025-10-02 15:11:04.509391 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-02 15:11:05.087576 | controller | skipping: Conditional result was False 2025-10-02 15:11:05.111527 | 2025-10-02 15:11:05.112503 | TASK [bindep : Remove bindep temp dir] 2025-10-02 15:11:05.508314 | controller | ok 2025-10-02 15:11:05.555323 | 2025-10-02 15:11:05.555403 | PLAY RECAP 2025-10-02 15:11:05.555445 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-10-02 15:11:05.555465 | 2025-10-02 15:11:05.731098 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-02 15:11:05.731997 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-02 15:11:06.352639 | 2025-10-02 15:11:06.352772 | PLAY [all] 2025-10-02 15:11:06.373168 | 2025-10-02 15:11:06.373254 | TASK [Abort when test_command variable is undefined] 2025-10-02 15:11:06.407563 | controller | skipping: Conditional result was False 2025-10-02 15:11:06.413228 | 2025-10-02 15:11:06.413300 | TASK [Convert test_command to list] 2025-10-02 15:11:06.457798 | controller | skipping: Conditional result was False 2025-10-02 15:11:06.463959 | 2025-10-02 15:11:06.464024 | TASK [Use test_command list] 2025-10-02 15:11:06.513346 | controller | ok 2025-10-02 15:11:06.518683 | 2025-10-02 15:11:06.518790 | LOOP [Run test_command] 2025-10-02 15:11:06.943973 | controller | no check to run 2025-10-02 15:11:06.944139 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.006308 2025-10-02 15:11:06.989125 | 2025-10-02 15:11:06.989265 | PLAY RECAP 2025-10-02 15:11:06.989321 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-02 15:11:06.989342 | 2025-10-02 15:11:07.122438 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-02 15:11:07.123391 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-02 15:11:07.748503 | 2025-10-02 15:11:07.748637 | PLAY [all] 2025-10-02 15:11:07.769116 | 2025-10-02 15:11:07.769209 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-02 15:11:08.180286 | controller | changed: non-zero return code 2025-10-02 15:11:08.186474 | 2025-10-02 15:11:08.186548 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-02 15:11:08.220833 | controller | skipping: Conditional result was False 2025-10-02 15:11:08.226889 | 2025-10-02 15:11:08.226969 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-02 15:11:08.257231 | 2025-10-02 15:11:08.257389 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-02 15:11:08.298260 | 2025-10-02 15:11:08.298515 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-02 15:11:08.328873 | controller | skipping: Conditional result was False 2025-10-02 15:11:08.335986 | 2025-10-02 15:11:08.336059 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-02 15:11:08.369926 | 2025-10-02 15:11:08.370088 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-02 15:11:08.404895 | controller | skipping: Conditional result was False 2025-10-02 15:11:08.411098 | 2025-10-02 15:11:08.411167 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-02 15:11:08.447588 | controller | skipping: Conditional result was False 2025-10-02 15:11:08.453861 | 2025-10-02 15:11:08.453934 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-02 15:11:08.498419 | controller | skipping: Conditional result was False 2025-10-02 15:11:08.558718 | 2025-10-02 15:11:08.558813 | PLAY RECAP 2025-10-02 15:11:08.558872 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-02 15:11:08.558894 | 2025-10-02 15:11:08.656657 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-02 15:11:08.657495 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-02 15:11:09.418592 | 2025-10-02 15:11:09.418749 | PLAY [all] 2025-10-02 15:11:09.440144 | 2025-10-02 15:11:09.440231 | TASK [include_role : fetch-output] 2025-10-02 15:11:09.480536 | controller | ok 2025-10-02 15:11:09.501687 | 2025-10-02 15:11:09.501898 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-02 15:11:09.546367 | controller | skipping: Conditional result was False 2025-10-02 15:11:09.552791 | 2025-10-02 15:11:09.552870 | TASK [fetch-output : Set log path for single node] 2025-10-02 15:11:09.594423 | controller | ok 2025-10-02 15:11:09.599662 | 2025-10-02 15:11:09.599748 | LOOP [fetch-output : Ensure local output dirs] 2025-10-02 15:11:10.058871 | controller -> localhost | ok: "/var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/work/logs" 2025-10-02 15:11:10.426395 | controller -> localhost | changed: "/var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/work/artifacts" 2025-10-02 15:11:10.642462 | controller -> localhost | changed: "/var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/work/docs" 2025-10-02 15:11:10.655345 | 2025-10-02 15:11:10.655430 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-02 15:11:11.348306 | controller | changed: .d..t...... ./ 2025-10-02 15:11:11.348494 | controller | changed: All items complete 2025-10-02 15:11:11.348522 | 2025-10-02 15:11:11.833456 | controller | changed: .d..t...... ./ 2025-10-02 15:11:12.288621 | controller | changed: .d..t...... ./ 2025-10-02 15:11:12.309640 | 2025-10-02 15:11:12.309726 | TASK [include_role : fetch-output-openshift] 2025-10-02 15:11:12.325097 | controller | skipping: Conditional result was False 2025-10-02 15:11:12.332348 | 2025-10-02 15:11:12.332429 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-02 15:11:12.700362 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.011523 2025-10-02 15:11:12.937512 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.013736 2025-10-02 15:11:12.971987 | 2025-10-02 15:11:12.972114 | PLAY [all] 2025-10-02 15:11:12.986267 | 2025-10-02 15:11:12.986330 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-10-02 15:11:13.488722 | controller | changed 2025-10-02 15:11:13.521468 | 2025-10-02 15:11:13.521549 | PLAY RECAP 2025-10-02 15:11:13.521599 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-02 15:11:13.521622 | 2025-10-02 15:11:13.623194 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-02 15:11:13.624031 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-10-02 15:11:14.227907 | 2025-10-02 15:11:14.228019 | PLAY [localhost] 2025-10-02 15:11:14.246053 | 2025-10-02 15:11:14.246132 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-02 15:11:14.579196 | localhost | changed 2025-10-02 15:11:14.584242 | 2025-10-02 15:11:14.584323 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-02 15:11:14.619461 | localhost | ok 2025-10-02 15:11:14.628451 | 2025-10-02 15:11:14.628522 | TASK [add-fileserver : Create SSH private key tempfile] 2025-10-02 15:11:14.987225 | localhost | changed 2025-10-02 15:11:14.997246 | 2025-10-02 15:11:14.997323 | TASK [add-fileserver : Create SSH private key from secret] 2025-10-02 15:11:15.628315 | localhost | changed 2025-10-02 15:11:15.633269 | 2025-10-02 15:11:15.633337 | TASK [add-fileserver : Add fileserver ssh key] 2025-10-02 15:11:16.038510 | localhost | Identity added: /var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/work/tmp/ansible.j0i5kn58 (/var/lib/zuul/builds/a28251c91f864e81a17e2e43180bdbd5/work/tmp/ansible.j0i5kn58) 2025-10-02 15:11:16.038816 | localhost | ok: Runtime: 0:00:00.012743 2025-10-02 15:11:16.043121 | 2025-10-02 15:11:16.043237 | TASK [add-fileserver : Remove SSH private key from disk] 2025-10-02 15:11:16.326866 | localhost | ok: Runtime: 0:00:00.010124 2025-10-02 15:11:16.332505 | 2025-10-02 15:11:16.332573 | TASK [add-fileserver : Add fileserver to inventory] 2025-10-02 15:11:16.386350 | localhost | changed 2025-10-02 15:11:16.396938 | 2025-10-02 15:11:16.397088 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-10-02 15:11:16.802290 | localhost | changed 2025-10-02 15:11:16.837716 | 2025-10-02 15:11:16.837798 | PLAY [localhost] 2025-10-02 15:11:16.849783 | 2025-10-02 15:11:16.849841 | TASK [Generate bulk log download script] 2025-10-02 15:11:16.868447 | localhost | ok 2025-10-02 15:11:16.883285 | 2025-10-02 15:11:16.883376 | TASK [local-log-download : Check API endpoint is defined] 2025-10-02 15:11:16.924360 | localhost | ok: All assertions passed 2025-10-02 15:11:16.930825 | 2025-10-02 15:11:16.931077 | TASK [local-log-download : Create download script] 2025-10-02 15:11:17.340946 | localhost -> localhost | changed 2025-10-02 15:11:17.355642 | 2025-10-02 15:11:17.355797 | TASK [Register quick-download link] 2025-10-02 15:11:17.374904 | localhost | ok 2025-10-02 15:11:17.414792 | 2025-10-02 15:11:17.414894 | PLAY [logserver.rdoproject.org] 2025-10-02 15:11:17.424723 | 2025-10-02 15:11:17.424783 | TASK [Set zuul-log-path fact] 2025-10-02 15:11:17.441510 | logserver.rdoproject.org | ok 2025-10-02 15:11:17.451363 | 2025-10-02 15:11:17.451434 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-02 15:11:17.478021 | logserver.rdoproject.org | ok 2025-10-02 15:11:17.483622 | 2025-10-02 15:11:17.483723 | TASK [upload-logs : Create log directories] 2025-10-02 15:11:18.136787 | logserver.rdoproject.org | changed 2025-10-02 15:11:18.144757 | 2025-10-02 15:11:18.144898 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-10-02 15:11:18.428259 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.008655 2025-10-02 15:11:18.433034 | 2025-10-02 15:11:18.433107 | TASK [upload-logs : Upload logs to log server] 2025-10-02 15:11:19.067939 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-10-02 15:11:19.071179 | 2025-10-02 15:11:19.071265 | LOOP [upload-logs : Compress console log and json output] 2025-10-02 15:11:19.116613 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 15:11:19.125224 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 15:11:19.135875 | 2025-10-02 15:11:19.136025 | LOOP [upload-logs : Upload compressed console log and json output] 2025-10-02 15:11:19.176504 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 15:11:19.176931 | 2025-10-02 15:11:19.185536 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-02 15:11:19.201219 | 2025-10-02 15:11:19.201361 | LOOP [upload-logs : Upload console log and json output]