2025-09-30 02:37:15.539642 | Job console starting... 2025-09-30 02:37:15.554175 | Updating repositories 2025-09-30 02:37:15.575575 | Preparing job workspace 2025-09-30 02:37:19.713077 | Running Ansible setup... 2025-09-30 02:37:24.572492 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-30 02:37:25.254070 | 2025-09-30 02:37:25.254218 | PLAY [localhost] 2025-09-30 02:37:25.263260 | 2025-09-30 02:37:25.263341 | TASK [Gathering Facts] 2025-09-30 02:37:26.183704 | localhost | ok 2025-09-30 02:37:26.197563 | 2025-09-30 02:37:26.197685 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-30 02:37:26.589407 | localhost -> localhost | changed 2025-09-30 02:37:26.597356 | 2025-09-30 02:37:26.597480 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-30 02:37:27.534455 | localhost -> localhost | changed 2025-09-30 02:37:27.543330 | 2025-09-30 02:37:27.543434 | TASK [Setup log path fact] 2025-09-30 02:37:27.571142 | localhost | ok 2025-09-30 02:37:27.593904 | 2025-09-30 02:37:27.594011 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-30 02:37:27.631945 | localhost | ok 2025-09-30 02:37:27.641798 | 2025-09-30 02:37:27.641925 | TASK [emit-job-header : Print job information] 2025-09-30 02:37:27.670172 | # Job Information 2025-09-30 02:37:27.670328 | Ansible Version: 2.15.12 2025-09-30 02:37:27.670355 | Job: cifmw-molecule-federation 2025-09-30 02:37:27.670375 | Pipeline: github-check 2025-09-30 02:37:27.670394 | Executor: ze01.softwarefactory-project.io 2025-09-30 02:37:27.670411 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333 2025-09-30 02:37:27.670430 | Log URL (when completed): https://logserver.rdoproject.org/f7b/rdoproject.org/f7b6208057374f20ab2cf398c08930dd/ 2025-09-30 02:37:27.670448 | Event ID: 1dc977c0-9da6-11f0-92a8-2c1c6d0a259d 2025-09-30 02:37:27.674056 | 2025-09-30 02:37:27.674119 | LOOP [emit-job-header : Print node information] 2025-09-30 02:37:27.779516 | localhost | ok: 2025-09-30 02:37:27.779669 | localhost | # Node Information 2025-09-30 02:37:27.779696 | localhost | Inventory Hostname: controller 2025-09-30 02:37:27.779719 | localhost | Hostname: np0005461242 2025-09-30 02:37:27.779739 | localhost | Username: zuul 2025-09-30 02:37:27.779760 | localhost | Distro: CentOS 9 2025-09-30 02:37:27.779778 | localhost | Provider: vexxhost-nodepool-tripleo 2025-09-30 02:37:27.779796 | localhost | Region: RegionOne 2025-09-30 02:37:27.779813 | localhost | Label: cloud-centos-9-stream-tripleo 2025-09-30 02:37:27.779830 | localhost | Product Name: OpenStack Nova 2025-09-30 02:37:27.779847 | localhost | Interface IP: 38.102.83.148 2025-09-30 02:37:27.822983 | 2025-09-30 02:37:27.823111 | PLAY [all] 2025-09-30 02:37:27.834232 | 2025-09-30 02:37:27.834294 | TASK [Gather network facts] 2025-09-30 02:37:28.378258 | controller | ok 2025-09-30 02:37:28.409095 | 2025-09-30 02:37:28.409206 | TASK [include_role : start-zuul-console] 2025-09-30 02:37:28.429156 | controller | ok 2025-09-30 02:37:28.444043 | 2025-09-30 02:37:28.444173 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-30 02:37:28.904308 | controller | ok 2025-09-30 02:37:28.922827 | 2025-09-30 02:37:28.922902 | TASK [include_role : add-build-sshkey] 2025-09-30 02:37:28.967308 | controller | ok 2025-09-30 02:37:28.982655 | 2025-09-30 02:37:28.982732 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-30 02:37:29.343227 | controller -> localhost | ok 2025-09-30 02:37:29.349443 | 2025-09-30 02:37:29.349514 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-30 02:37:29.397823 | controller | ok 2025-09-30 02:37:29.418316 | controller | included: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-30 02:37:29.434294 | 2025-09-30 02:37:29.434402 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-30 02:37:30.070368 | controller -> localhost | Generating public/private rsa key pair. 2025-09-30 02:37:30.070571 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/work/f7b6208057374f20ab2cf398c08930dd_id_rsa. 2025-09-30 02:37:30.070602 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/work/f7b6208057374f20ab2cf398c08930dd_id_rsa.pub. 2025-09-30 02:37:30.070623 | controller -> localhost | The key fingerprint is: 2025-09-30 02:37:30.070642 | controller -> localhost | SHA256:X/dsWhEGX9OwNQFZaLz2Ayvo9pH0iXSXW9C+LOd8pw0 zuul-build-sshkey 2025-09-30 02:37:30.070660 | controller -> localhost | The key's randomart image is: 2025-09-30 02:37:30.070678 | controller -> localhost | +---[RSA 3072]----+ 2025-09-30 02:37:30.070695 | controller -> localhost | | .o**=| 2025-09-30 02:37:30.070713 | controller -> localhost | | =o+=| 2025-09-30 02:37:30.070729 | controller -> localhost | | . ++.| 2025-09-30 02:37:30.070747 | controller -> localhost | | +.oo| 2025-09-30 02:37:30.070764 | controller -> localhost | | S .oo.=+o| 2025-09-30 02:37:30.070781 | controller -> localhost | | ooo=o+==| 2025-09-30 02:37:30.070797 | controller -> localhost | | . .+.+E=*| 2025-09-30 02:37:30.070813 | controller -> localhost | | o . =*o| 2025-09-30 02:37:30.070829 | controller -> localhost | | . .. o++| 2025-09-30 02:37:30.070846 | controller -> localhost | +----[SHA256]-----+ 2025-09-30 02:37:30.070889 | controller -> localhost | ok: Runtime: 0:00:00.162764 2025-09-30 02:37:30.076674 | 2025-09-30 02:37:30.076738 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-30 02:37:30.135782 | controller | ok 2025-09-30 02:37:30.145815 | controller | included: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-30 02:37:30.163493 | 2025-09-30 02:37:30.163558 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-30 02:37:30.215596 | controller | skipping: Conditional result was False 2025-09-30 02:37:30.238346 | 2025-09-30 02:37:30.238462 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-30 02:37:30.811660 | controller | changed 2025-09-30 02:37:30.821418 | 2025-09-30 02:37:30.821516 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-30 02:37:31.097392 | controller | ok 2025-09-30 02:37:31.103517 | 2025-09-30 02:37:31.103589 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-30 02:37:32.242327 | controller | changed 2025-09-30 02:37:32.266033 | 2025-09-30 02:37:32.266153 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-30 02:37:33.291345 | controller | changed 2025-09-30 02:37:33.300044 | 2025-09-30 02:37:33.300139 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-30 02:37:33.348591 | controller | skipping: Conditional result was False 2025-09-30 02:37:33.355564 | 2025-09-30 02:37:33.355659 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-30 02:37:33.908314 | controller -> localhost | changed 2025-09-30 02:37:33.927698 | 2025-09-30 02:37:33.927825 | TASK [add-build-sshkey : Add back temp key] 2025-09-30 02:37:34.379994 | controller -> localhost | Identity added: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/work/f7b6208057374f20ab2cf398c08930dd_id_rsa (zuul-build-sshkey) 2025-09-30 02:37:34.380196 | controller -> localhost | ok: Runtime: 0:00:00.010175 2025-09-30 02:37:34.388641 | 2025-09-30 02:37:34.388719 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-30 02:37:35.022860 | controller | ok 2025-09-30 02:37:35.033525 | 2025-09-30 02:37:35.033615 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-30 02:37:35.077863 | controller | skipping: Conditional result was False 2025-09-30 02:37:35.088536 | 2025-09-30 02:37:35.088613 | TASK [include_role : validate-host] 2025-09-30 02:37:35.183844 | controller | ok 2025-09-30 02:37:35.229299 | 2025-09-30 02:37:35.229442 | TASK [validate-host : Define zuul_info_dir fact] 2025-09-30 02:37:35.293772 | controller | ok 2025-09-30 02:37:35.299972 | 2025-09-30 02:37:35.300075 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-09-30 02:37:35.953928 | controller -> localhost | ok 2025-09-30 02:37:35.959437 | 2025-09-30 02:37:35.959534 | TASK [validate-host : Collect information about the host] 2025-09-30 02:37:36.829881 | controller | ok 2025-09-30 02:37:36.845335 | 2025-09-30 02:37:36.845489 | TASK [validate-host : Sanitize hostname] 2025-09-30 02:37:36.962817 | controller | ok 2025-09-30 02:37:36.967813 | 2025-09-30 02:37:36.967882 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-09-30 02:37:38.129587 | controller -> localhost | changed 2025-09-30 02:37:38.136144 | 2025-09-30 02:37:38.136222 | TASK [validate-host : Collect information about zuul worker] 2025-09-30 02:37:38.653559 | controller | ok 2025-09-30 02:37:38.659170 | 2025-09-30 02:37:38.659266 | TASK [validate-host : Write out all zuul information for each host] 2025-09-30 02:37:39.434656 | controller -> localhost | changed 2025-09-30 02:37:39.451682 | 2025-09-30 02:37:39.452320 | TASK [include_role : prepare-workspace-openshift] 2025-09-30 02:37:39.518139 | controller | skipping: Conditional result was False 2025-09-30 02:37:39.529544 | 2025-09-30 02:37:39.529688 | TASK [include_role : remove-zuul-sshkey] 2025-09-30 02:37:39.576262 | controller | skipping: Conditional result was False 2025-09-30 02:37:39.581847 | 2025-09-30 02:37:39.581924 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-30 02:37:39.947410 | controller | ok: "logs" 2025-09-30 02:37:39.947648 | controller | ok: All items complete 2025-09-30 02:37:39.947675 | 2025-09-30 02:37:40.185558 | controller | ok: "artifacts" 2025-09-30 02:37:40.465218 | controller | ok: "docs" 2025-09-30 02:37:40.478969 | 2025-09-30 02:37:40.479134 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-30 02:37:40.814672 | controller | changed: "logs" 2025-09-30 02:37:41.101426 | controller | changed: "artifacts" 2025-09-30 02:37:41.376378 | controller | changed: "docs" 2025-09-30 02:37:41.407285 | 2025-09-30 02:37:41.407382 | PLAY RECAP 2025-09-30 02:37:41.407422 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-09-30 02:37:41.407448 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-30 02:37:41.407466 | 2025-09-30 02:37:41.548007 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-30 02:37:41.548903 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-09-30 02:37:42.483628 | 2025-09-30 02:37:42.483764 | PLAY [localhost] 2025-09-30 02:37:42.552720 | 2025-09-30 02:37:42.552878 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-09-30 02:37:43.404794 | localhost | ok 2025-09-30 02:37:43.422076 | 2025-09-30 02:37:43.422213 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-09-30 02:37:44.311026 | localhost | changed 2025-09-30 02:37:44.356873 | 2025-09-30 02:37:44.356982 | PLAY [all] 2025-09-30 02:37:44.384127 | 2025-09-30 02:37:44.384252 | TASK [include_role : prepare-workspace] 2025-09-30 02:37:44.441213 | controller | ok 2025-09-30 02:37:44.472682 | 2025-09-30 02:37:44.472824 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-30 02:37:45.020931 | controller | ok 2025-09-30 02:37:45.033524 | 2025-09-30 02:37:45.033651 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-30 02:37:47.569298 | controller | Output suppressed because no_log was given 2025-09-30 02:37:47.588647 | 2025-09-30 02:37:47.588753 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-30 02:37:47.872702 | controller | changed: "logs" 2025-09-30 02:37:48.093733 | controller | changed: "artifacts" 2025-09-30 02:37:48.354871 | controller | changed: "docs" 2025-09-30 02:37:48.367440 | 2025-09-30 02:37:48.367565 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-30 02:37:48.684603 | controller | changed: "logs" 2025-09-30 02:37:48.684822 | controller | changed: All items complete 2025-09-30 02:37:48.684849 | 2025-09-30 02:37:48.902000 | controller | changed: "artifacts" 2025-09-30 02:37:49.168568 | controller | changed: "docs" 2025-09-30 02:37:49.190592 | 2025-09-30 02:37:49.190695 | TASK [Check if worker can sudo] 2025-09-30 02:37:50.259068 | controller | ok: Runtime: 0:00:00.049195 2025-09-30 02:37:50.265266 | 2025-09-30 02:37:50.265337 | TASK [configure-mirrors : Gather needed facts] 2025-09-30 02:37:50.522864 | controller | skipping: Conditional result was False 2025-09-30 02:37:50.661483 | 2025-09-30 02:37:50.661605 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-09-30 02:37:50.783676 | controller | ok 2025-09-30 02:37:50.801576 | controller | included: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-09-30 02:37:50.822307 | 2025-09-30 02:37:50.822445 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-09-30 02:37:51.212739 | controller | ok 2025-09-30 02:37:51.224743 | 2025-09-30 02:37:51.224847 | LOOP [configure-mirrors : Include OS-specific variables] 2025-09-30 02:37:51.464382 | controller | ok: "/var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-09-30 02:37:51.472501 | 2025-09-30 02:37:51.472610 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-09-30 02:37:52.537607 | controller | changed 2025-09-30 02:37:52.558798 | 2025-09-30 02:37:52.558919 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-09-30 02:37:52.725926 | controller | ok: "/var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-09-30 02:37:52.726101 | controller | ok: All items complete 2025-09-30 02:37:52.726128 | 2025-09-30 02:37:52.833875 | controller | included: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-09-30 02:37:52.847328 | 2025-09-30 02:37:52.847391 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-09-30 02:37:53.940736 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-09-30 02:37:55.070968 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-09-30 02:37:55.089550 | 2025-09-30 02:37:55.089715 | TASK [configure-mirrors : Disable deltrarpm] 2025-09-30 02:37:55.609835 | controller | changed: section and option added 2025-09-30 02:37:55.636631 | 2025-09-30 02:37:55.636728 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-09-30 02:37:57.310960 | controller | 29 files removed 2025-09-30 02:37:57.311186 | controller | ok: Item: dnf clean all Runtime: 0:00:01.274341 2025-09-30 02:37:57.311225 | controller | changed: All items complete 2025-09-30 02:37:57.311246 | 2025-09-30 02:38:08.371393 | 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-09-30 02:38:08.371498 | controller | DNF version: 4.14.0 2025-09-30 02:38:08.371523 | controller | cachedir: /var/cache/dnf 2025-09-30 02:38:08.371544 | controller | Making cache files for all metadata files. 2025-09-30 02:38:08.371563 | controller | baseos: has expired and will be refreshed. 2025-09-30 02:38:08.371616 | controller | appstream: has expired and will be refreshed. 2025-09-30 02:38:08.371644 | controller | crb: has expired and will be refreshed. 2025-09-30 02:38:08.371671 | controller | extras-common: has expired and will be refreshed. 2025-09-30 02:38:08.371689 | controller | repo: downloading from remote: baseos 2025-09-30 02:38:08.371707 | controller | CentOS Stream 9 - BaseOS 19 MB/s | 8.8 MB 00:00 2025-09-30 02:38:08.371723 | controller | baseos: using metadata from Mon 22 Sep 2025 10:29:43 AM EDT. 2025-09-30 02:38:08.371740 | controller | repo: downloading from remote: appstream 2025-09-30 02:38:08.371757 | controller | CentOS Stream 9 - AppStream 82 MB/s | 25 MB 00:00 2025-09-30 02:38:08.371774 | controller | appstream: using metadata from Mon 22 Sep 2025 10:33:24 AM EDT. 2025-09-30 02:38:08.371791 | controller | repo: downloading from remote: crb 2025-09-30 02:38:08.371812 | controller | CentOS Stream 9 - CRB 88 MB/s | 7.1 MB 00:00 2025-09-30 02:38:08.371830 | controller | crb: using metadata from Mon 22 Sep 2025 10:37:51 AM EDT. 2025-09-30 02:38:08.371848 | controller | repo: downloading from remote: extras-common 2025-09-30 02:38:08.371865 | controller | CentOS Stream 9 - Extras packages 1.2 MB/s | 20 kB 00:00 2025-09-30 02:38:08.371883 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-09-30 02:38:08.371900 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-09-30 02:38:08.371917 | controller | Completion plugin: Generating completion cache... 2025-09-30 02:38:08.371938 | controller | Metadata cache created. 2025-09-30 02:38:08.371965 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.696543 2025-09-30 02:38:08.388988 | 2025-09-30 02:38:08.389113 | PLAY RECAP 2025-09-30 02:38:08.389166 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-09-30 02:38:08.389204 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-30 02:38:08.389229 | 2025-09-30 02:38:08.503557 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-09-30 02:38:08.504387 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-30 02:38:09.033353 | 2025-09-30 02:38:09.033470 | PLAY [all] 2025-09-30 02:38:09.054934 | 2025-09-30 02:38:09.055066 | TASK [Install binary dependencies] 2025-09-30 02:38:09.104642 | controller | ok 2025-09-30 02:38:09.125538 | 2025-09-30 02:38:09.125671 | TASK [bindep : Include find tasks] 2025-09-30 02:38:09.154597 | controller | ok 2025-09-30 02:38:09.162834 | controller | included: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-30 02:38:09.168822 | 2025-09-30 02:38:09.168887 | TASK [bindep : Look for bindep.txt] 2025-09-30 02:38:09.576885 | controller | ok 2025-09-30 02:38:09.607145 | 2025-09-30 02:38:09.607356 | TASK [bindep : Define bindep_file fact] 2025-09-30 02:38:09.654672 | controller | ok 2025-09-30 02:38:09.662135 | 2025-09-30 02:38:09.662228 | TASK [bindep : Look for other-requirements.txt] 2025-09-30 02:38:09.676823 | controller | skipping: Conditional result was False 2025-09-30 02:38:09.684960 | 2025-09-30 02:38:09.685083 | TASK [bindep : Define bindep_file fact] 2025-09-30 02:38:09.710123 | controller | skipping: Conditional result was False 2025-09-30 02:38:09.718539 | 2025-09-30 02:38:09.718695 | TASK [bindep : Look for bindep fallback file] 2025-09-30 02:38:09.744601 | controller | skipping: Conditional result was False 2025-09-30 02:38:09.753541 | 2025-09-30 02:38:09.753658 | TASK [bindep : Define bindep_file fact] 2025-09-30 02:38:09.782898 | controller | skipping: Conditional result was False 2025-09-30 02:38:09.788959 | 2025-09-30 02:38:09.789041 | TASK [bindep : Include bindep tasks] 2025-09-30 02:38:09.819213 | controller | ok 2025-09-30 02:38:09.826309 | controller | included: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-09-30 02:38:09.834873 | 2025-09-30 02:38:09.834949 | TASK [bindep : Look for bindep command] 2025-09-30 02:38:09.859072 | controller | skipping: Conditional result was False 2025-09-30 02:38:09.865435 | 2025-09-30 02:38:09.865495 | TASK [bindep : Check for system bindep] 2025-09-30 02:38:10.402965 | controller | ok: Runtime: 0:00:00.008066 2025-09-30 02:38:10.408987 | 2025-09-30 02:38:10.409074 | TASK [bindep : Define bindep_command fact] 2025-09-30 02:38:10.433570 | controller | skipping: Conditional result was False 2025-09-30 02:38:10.440902 | 2025-09-30 02:38:10.441003 | TASK [bindep : Include install tasks] 2025-09-30 02:38:10.473629 | controller | ok 2025-09-30 02:38:10.485569 | controller | included: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-09-30 02:38:10.498756 | 2025-09-30 02:38:10.498863 | TASK [bindep : Create temp dir for bindep] 2025-09-30 02:38:10.924302 | controller | changed 2025-09-30 02:38:10.937840 | 2025-09-30 02:38:10.938003 | TASK [Ensure we have pip dependencies] 2025-09-30 02:38:10.966408 | controller | ok 2025-09-30 02:38:11.016123 | 2025-09-30 02:38:11.016260 | TASK [ensure-pip : Check if pip is installed] 2025-09-29 22:38:11.342330 | controller | /usr/bin/pip3 2025-09-29 22:38:11.363987 | controller | /usr/bin/python3: No module named wheel 2025-09-30 02:38:11.560102 | controller | ok: Runtime: 0:00:00.032470 2025-09-30 02:38:11.565663 | 2025-09-30 02:38:11.565745 | LOOP [ensure-pip : Install pip from packages] 2025-09-30 02:38:11.589431 | controller | ok: "/var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-09-30 02:38:11.598256 | controller | included: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-09-30 02:38:11.608936 | 2025-09-30 02:38:11.609246 | TASK [ensure-pip : Install Python 3 pip] 2025-09-30 02:38:14.516989 | controller | changed 2025-09-30 02:38:14.536994 | 2025-09-30 02:38:14.537146 | TASK [ensure-pip : Check for EPEL repository] 2025-09-30 02:38:14.602701 | controller | skipping: Conditional result was False 2025-09-30 02:38:14.612331 | 2025-09-30 02:38:14.612499 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-09-30 02:38:14.659327 | controller | skipping: Conditional result was False 2025-09-30 02:38:14.669921 | 2025-09-30 02:38:14.670064 | TASK [ensure-pip : Install Python 2 pip] 2025-09-30 02:38:14.725601 | controller | skipping: Conditional result was False 2025-09-30 02:38:14.736072 | 2025-09-30 02:38:14.736172 | TASK [ensure-pip : Ensure setuptools] 2025-09-30 02:38:14.765541 | controller | skipping: Conditional result was False 2025-09-30 02:38:14.774528 | 2025-09-30 02:38:14.774642 | TASK [ensure-pip : Check for ensurepip module] 2025-09-30 02:38:15.309100 | controller | skipping: Conditional result was False 2025-09-30 02:38:15.324776 | 2025-09-30 02:38:15.324943 | TASK [ensure-pip : Ensure python3-venv] 2025-09-30 02:38:15.352354 | controller | skipping: Conditional result was False 2025-09-30 02:38:15.365758 | 2025-09-30 02:38:15.366055 | TASK [ensure-pip : Install pip from source] 2025-09-30 02:38:15.393347 | controller | skipping: Conditional result was False 2025-09-30 02:38:15.408433 | 2025-09-30 02:38:15.408618 | TASK [ensure-pip : Probe for venv python full path] 2025-09-29 22:38:15.758472 | controller | /usr/bin/python3 2025-09-30 02:38:15.961672 | controller | ok: Runtime: 0:00:00.005990 2025-09-30 02:38:15.970283 | 2025-09-30 02:38:15.970383 | TASK [ensure-pip : Set host default] 2025-09-30 02:38:16.044211 | controller | ok 2025-09-30 02:38:16.051788 | 2025-09-30 02:38:16.051882 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-09-30 02:38:16.128048 | controller | ok 2025-09-30 02:38:16.144881 | 2025-09-30 02:38:16.145092 | TASK [bindep : Install bindep into temporary venv] 2025-09-30 02:38:21.725774 | controller | changed 2025-09-30 02:38:21.738671 | 2025-09-30 02:38:21.738818 | TASK [bindep : Define bindep_command] 2025-09-30 02:38:21.784151 | controller | ok 2025-09-30 02:38:21.800841 | 2025-09-30 02:38:21.801112 | LOOP [bindep : Include package tasks] 2025-09-30 02:38:21.897272 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-09-30 02:38:21.897674 | controller | ok: All items complete 2025-09-30 02:38:21.897750 | 2025-09-30 02:38:21.916384 | controller | included: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-09-30 02:38:21.927583 | 2025-09-30 02:38:21.927653 | TASK [bindep : Define bindep_run fact] 2025-09-30 02:38:21.976786 | controller | ok 2025-09-30 02:38:21.981932 | 2025-09-30 02:38:21.981995 | TASK [bindep : Get list of packages to install from bindep] 2025-09-29 22:38:23.640872 | controller | podman 2025-09-29 22:38:23.677895 | controller | python3-jmespath 2025-09-29 22:38:23.677989 | controller | python3-libvirt 2025-09-29 22:38:23.678011 | controller | python3-lxml 2025-09-29 22:38:23.678033 | controller | python3-netaddr 2025-09-30 02:38:24.026143 | controller | ok: Runtime: 0:00:01.381433 2025-09-30 02:38:24.039462 | 2025-09-30 02:38:24.039796 | TASK [bindep : Install distro packages from bindep] 2025-09-30 02:39:43.296744 | controller | changed 2025-09-30 02:39:43.307162 | 2025-09-30 02:39:43.307288 | TASK [bindep : Check that packages are installed] 2025-09-30 02:39:45.358238 | controller | ok: Runtime: 0:00:01.234852 2025-09-30 02:39:45.370684 | 2025-09-30 02:39:45.370838 | TASK [bindep : Fail if we cannot install all packages] 2025-09-30 02:39:45.408449 | controller | skipping: Conditional result was False 2025-09-30 02:39:45.434548 | 2025-09-30 02:39:45.434723 | TASK [Run test-setup role] 2025-09-30 02:39:45.463979 | controller | ok 2025-09-30 02:39:45.496539 | 2025-09-30 02:39:45.496682 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-30 02:39:45.756103 | controller | ok 2025-09-30 02:39:45.767277 | 2025-09-30 02:39:45.767433 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-30 02:39:46.315982 | controller | skipping: Conditional result was False 2025-09-30 02:39:46.360895 | 2025-09-30 02:39:46.361100 | TASK [bindep : Remove bindep temp dir] 2025-09-30 02:39:46.843085 | controller | ok 2025-09-30 02:39:46.860121 | 2025-09-30 02:39:46.860232 | PLAY RECAP 2025-09-30 02:39:46.860284 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-09-30 02:39:46.860312 | 2025-09-30 02:39:46.959210 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-30 02:39:46.960470 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-09-30 02:39:47.508201 | 2025-09-30 02:39:47.508335 | PLAY [all] 2025-09-30 02:39:47.528950 | 2025-09-30 02:39:47.529081 | TASK [Abort when test_command variable is undefined] 2025-09-30 02:39:47.564775 | controller | skipping: Conditional result was False 2025-09-30 02:39:47.570761 | 2025-09-30 02:39:47.570849 | TASK [Convert test_command to list] 2025-09-30 02:39:47.605814 | controller | skipping: Conditional result was False 2025-09-30 02:39:47.613517 | 2025-09-30 02:39:47.613607 | TASK [Use test_command list] 2025-09-30 02:39:47.662906 | controller | ok 2025-09-30 02:39:47.668828 | 2025-09-30 02:39:47.668895 | LOOP [Run test_command] 2025-09-30 02:39:48.104118 | controller | no check to run 2025-09-30 02:39:48.104475 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.009042 2025-09-30 02:39:48.134610 | 2025-09-30 02:39:48.134754 | PLAY RECAP 2025-09-30 02:39:48.134801 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-09-30 02:39:48.134822 | 2025-09-30 02:39:48.240303 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-09-30 02:39:48.241181 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-30 02:39:48.869178 | 2025-09-30 02:39:48.869316 | PLAY [all] 2025-09-30 02:39:48.890764 | 2025-09-30 02:39:48.890889 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-30 02:39:49.267924 | controller | changed: non-zero return code 2025-09-30 02:39:49.273286 | 2025-09-30 02:39:49.273358 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-30 02:39:49.286964 | controller | skipping: Conditional result was False 2025-09-30 02:39:49.292611 | 2025-09-30 02:39:49.292682 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-30 02:39:49.312227 | 2025-09-30 02:39:49.312379 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-30 02:39:49.331318 | 2025-09-30 02:39:49.331469 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-30 02:39:49.344469 | controller | skipping: Conditional result was False 2025-09-30 02:39:49.350457 | 2025-09-30 02:39:49.350526 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-30 02:39:49.368880 | 2025-09-30 02:39:49.369064 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-30 02:39:49.382083 | controller | skipping: Conditional result was False 2025-09-30 02:39:49.389441 | 2025-09-30 02:39:49.389524 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-30 02:39:49.402441 | controller | skipping: Conditional result was False 2025-09-30 02:39:49.408163 | 2025-09-30 02:39:49.408234 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-30 02:39:49.421205 | controller | skipping: Conditional result was False 2025-09-30 02:39:49.449236 | 2025-09-30 02:39:49.449331 | PLAY RECAP 2025-09-30 02:39:49.449390 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-30 02:39:49.449420 | 2025-09-30 02:39:49.544147 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-30 02:39:49.544981 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-30 02:39:50.149344 | 2025-09-30 02:39:50.149642 | PLAY [all] 2025-09-30 02:39:50.169066 | 2025-09-30 02:39:50.169187 | TASK [include_role : fetch-output] 2025-09-30 02:39:50.198169 | controller | ok 2025-09-30 02:39:50.215832 | 2025-09-30 02:39:50.215965 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-30 02:39:50.260625 | controller | skipping: Conditional result was False 2025-09-30 02:39:50.269038 | 2025-09-30 02:39:50.269164 | TASK [fetch-output : Set log path for single node] 2025-09-30 02:39:50.301213 | controller | ok 2025-09-30 02:39:50.308507 | 2025-09-30 02:39:50.308619 | LOOP [fetch-output : Ensure local output dirs] 2025-09-30 02:39:50.741676 | controller -> localhost | ok: "/var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/work/logs" 2025-09-30 02:39:51.047225 | controller -> localhost | changed: "/var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/work/artifacts" 2025-09-30 02:39:51.298192 | controller -> localhost | changed: "/var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/work/docs" 2025-09-30 02:39:51.310582 | 2025-09-30 02:39:51.310722 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-30 02:39:52.098822 | controller | changed: .d..t...... ./ 2025-09-30 02:39:52.099243 | controller | changed: All items complete 2025-09-30 02:39:52.099304 | 2025-09-30 02:39:52.671118 | controller | changed: .d..t...... ./ 2025-09-30 02:39:53.186104 | controller | changed: .d..t...... ./ 2025-09-30 02:39:53.213309 | 2025-09-30 02:39:53.213448 | TASK [include_role : fetch-output-openshift] 2025-09-30 02:39:53.228092 | controller | skipping: Conditional result was False 2025-09-30 02:39:53.237216 | 2025-09-30 02:39:53.237336 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-30 02:39:53.680467 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.013332 2025-09-30 02:39:53.935358 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.023789 2025-09-30 02:39:53.985069 | 2025-09-30 02:39:53.985194 | PLAY [all] 2025-09-30 02:39:54.006387 | 2025-09-30 02:39:54.006522 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-09-30 02:39:54.461545 | controller | changed 2025-09-30 02:39:54.507127 | 2025-09-30 02:39:54.507250 | PLAY RECAP 2025-09-30 02:39:54.507308 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-09-30 02:39:54.507337 | 2025-09-30 02:39:54.617287 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-30 02:39:54.618144 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-09-30 02:39:55.246455 | 2025-09-30 02:39:55.246601 | PLAY [localhost] 2025-09-30 02:39:55.266042 | 2025-09-30 02:39:55.266163 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-30 02:39:55.666719 | localhost | changed 2025-09-30 02:39:55.677745 | 2025-09-30 02:39:55.677925 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-30 02:39:55.704324 | localhost | ok 2025-09-30 02:39:55.723408 | 2025-09-30 02:39:55.723565 | TASK [add-fileserver : Create SSH private key tempfile] 2025-09-30 02:39:56.132282 | localhost | changed 2025-09-30 02:39:56.140760 | 2025-09-30 02:39:56.140855 | TASK [add-fileserver : Create SSH private key from secret] 2025-09-30 02:39:56.840871 | localhost | changed 2025-09-30 02:39:56.845971 | 2025-09-30 02:39:56.846058 | TASK [add-fileserver : Add fileserver ssh key] 2025-09-30 02:39:57.390856 | localhost | Identity added: /var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/work/tmp/ansible.r1hwgll1 (/var/lib/zuul/builds/f7b6208057374f20ab2cf398c08930dd/work/tmp/ansible.r1hwgll1) 2025-09-30 02:39:57.391193 | localhost | ok: Runtime: 0:00:00.008124 2025-09-30 02:39:57.400696 | 2025-09-30 02:39:57.400858 | TASK [add-fileserver : Remove SSH private key from disk] 2025-09-30 02:39:57.701136 | localhost | ok: Runtime: 0:00:00.004429 2025-09-30 02:39:57.711760 | 2025-09-30 02:39:57.711902 | TASK [add-fileserver : Add fileserver to inventory] 2025-09-30 02:39:57.778525 | localhost | changed 2025-09-30 02:39:57.786677 | 2025-09-30 02:39:57.786785 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-09-30 02:39:58.216942 | localhost | changed 2025-09-30 02:39:58.237996 | 2025-09-30 02:39:58.238119 | PLAY [localhost] 2025-09-30 02:39:58.250969 | 2025-09-30 02:39:58.251115 | TASK [Generate bulk log download script] 2025-09-30 02:39:58.269364 | localhost | ok 2025-09-30 02:39:58.281823 | 2025-09-30 02:39:58.281936 | TASK [local-log-download : Check API endpoint is defined] 2025-09-30 02:39:58.310841 | localhost | ok: All assertions passed 2025-09-30 02:39:58.315714 | 2025-09-30 02:39:58.315795 | TASK [local-log-download : Create download script] 2025-09-30 02:39:58.756773 | localhost -> localhost | changed 2025-09-30 02:39:58.765786 | 2025-09-30 02:39:58.765883 | TASK [Register quick-download link] 2025-09-30 02:39:58.783531 | localhost | ok 2025-09-30 02:39:58.827488 | 2025-09-30 02:39:58.827588 | PLAY [logserver.rdoproject.org] 2025-09-30 02:39:58.838136 | 2025-09-30 02:39:58.838211 | TASK [Set zuul-log-path fact] 2025-09-30 02:39:58.855061 | logserver.rdoproject.org | ok 2025-09-30 02:39:58.864679 | 2025-09-30 02:39:58.864761 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-30 02:39:58.901971 | logserver.rdoproject.org | ok 2025-09-30 02:39:58.907485 | 2025-09-30 02:39:58.907551 | TASK [upload-logs : Create log directories] 2025-09-30 02:39:59.670090 | logserver.rdoproject.org | changed 2025-09-30 02:39:59.676812 | 2025-09-30 02:39:59.676954 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-09-30 02:40:00.000311 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.006410 2025-09-30 02:40:00.006756 | 2025-09-30 02:40:00.006857 | TASK [upload-logs : Upload logs to log server] 2025-09-30 02:40:00.709893 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-09-30 02:40:00.716283 | 2025-09-30 02:40:00.716438 | LOOP [upload-logs : Compress console log and json output] 2025-09-30 02:40:00.792199 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 02:40:00.818219 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 02:40:00.834135 | 2025-09-30 02:40:00.834320 | LOOP [upload-logs : Upload compressed console log and json output] 2025-09-30 02:40:00.903226 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 02:40:00.903662 | 2025-09-30 02:40:00.908231 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 02:40:00.919168 | 2025-09-30 02:40:00.919355 | LOOP [upload-logs : Upload console log and json output]