2025-09-30 05:00:25.267152 | Job console starting... 2025-09-30 05:00:25.276945 | Updating repositories 2025-09-30 05:00:25.303951 | Preparing job workspace 2025-09-30 05:00:29.361050 | Running Ansible setup... 2025-09-30 05:00:33.198911 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-30 05:00:33.894365 | 2025-09-30 05:00:33.894487 | PLAY [localhost] 2025-09-30 05:00:33.903556 | 2025-09-30 05:00:33.903661 | TASK [Gathering Facts] 2025-09-30 05:00:35.082379 | localhost | ok 2025-09-30 05:00:35.102601 | 2025-09-30 05:00:35.102770 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-30 05:00:35.590492 | localhost -> localhost | changed 2025-09-30 05:00:35.596383 | 2025-09-30 05:00:35.596472 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-30 05:00:36.841972 | localhost -> localhost | changed 2025-09-30 05:00:36.850575 | 2025-09-30 05:00:36.850669 | TASK [Setup log path fact] 2025-09-30 05:00:36.889482 | localhost | ok 2025-09-30 05:00:36.917154 | 2025-09-30 05:00:36.917257 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-30 05:00:36.955775 | localhost | ok 2025-09-30 05:00:36.963566 | 2025-09-30 05:00:36.963633 | TASK [emit-job-header : Print job information] 2025-09-30 05:00:36.993113 | # Job Information 2025-09-30 05:00:36.993325 | Ansible Version: 2.15.12 2025-09-30 05:00:36.993354 | Job: cifmw-molecule-krb_request 2025-09-30 05:00:36.993375 | Pipeline: github-check 2025-09-30 05:00:36.993393 | Executor: ze03.softwarefactory-project.io 2025-09-30 05:00:36.993412 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333 2025-09-30 05:00:36.993431 | Log URL (when completed): https://logserver.rdoproject.org/c7f/rdoproject.org/c7fda277a9df4290be1d8efb4f621041/ 2025-09-30 05:00:36.993450 | Event ID: 3089cae0-9dba-11f0-9d66-59f03df1d747 2025-09-30 05:00:36.997378 | 2025-09-30 05:00:36.997466 | LOOP [emit-job-header : Print node information] 2025-09-30 05:00:37.106091 | localhost | ok: 2025-09-30 05:00:37.106246 | localhost | # Node Information 2025-09-30 05:00:37.106273 | localhost | Inventory Hostname: controller 2025-09-30 05:00:37.106306 | localhost | Hostname: np0005461560 2025-09-30 05:00:37.106326 | localhost | Username: zuul 2025-09-30 05:00:37.106347 | localhost | Distro: CentOS 9 2025-09-30 05:00:37.106365 | localhost | Provider: vexxhost-nodepool-tripleo 2025-09-30 05:00:37.106382 | localhost | Region: RegionOne 2025-09-30 05:00:37.106399 | localhost | Label: cloud-centos-9-stream-tripleo 2025-09-30 05:00:37.106415 | localhost | Product Name: OpenStack Nova 2025-09-30 05:00:37.106432 | localhost | Interface IP: 38.102.83.65 2025-09-30 05:00:37.163043 | 2025-09-30 05:00:37.163146 | PLAY [all] 2025-09-30 05:00:37.172189 | 2025-09-30 05:00:37.172267 | TASK [Gather network facts] 2025-09-30 05:00:37.652139 | controller | ok 2025-09-30 05:00:37.667430 | 2025-09-30 05:00:37.667516 | TASK [include_role : start-zuul-console] 2025-09-30 05:00:37.690657 | controller | ok 2025-09-30 05:00:37.704165 | 2025-09-30 05:00:37.704257 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-30 05:00:38.093231 | controller | ok 2025-09-30 05:00:38.107133 | 2025-09-30 05:00:38.107218 | TASK [include_role : add-build-sshkey] 2025-09-30 05:00:38.126678 | controller | ok 2025-09-30 05:00:38.142557 | 2025-09-30 05:00:38.142649 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-30 05:00:38.427502 | controller -> localhost | ok 2025-09-30 05:00:38.433195 | 2025-09-30 05:00:38.433262 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-30 05:00:38.461016 | controller | ok 2025-09-30 05:00:38.476364 | controller | included: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-30 05:00:38.482365 | 2025-09-30 05:00:38.482435 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-30 05:00:39.272070 | controller -> localhost | Generating public/private rsa key pair. 2025-09-30 05:00:39.272252 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/work/c7fda277a9df4290be1d8efb4f621041_id_rsa. 2025-09-30 05:00:39.272284 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/work/c7fda277a9df4290be1d8efb4f621041_id_rsa.pub. 2025-09-30 05:00:39.272306 | controller -> localhost | The key fingerprint is: 2025-09-30 05:00:39.272327 | controller -> localhost | SHA256:2VeHWyTNf0PjtA/0XSUDTLadG3OyWDOmR90cgZ17Njw zuul-build-sshkey 2025-09-30 05:00:39.272346 | controller -> localhost | The key's randomart image is: 2025-09-30 05:00:39.272365 | controller -> localhost | +---[RSA 3072]----+ 2025-09-30 05:00:39.272384 | controller -> localhost | | o+.*=*| 2025-09-30 05:00:39.272405 | controller -> localhost | | ..+./*| 2025-09-30 05:00:39.272424 | controller -> localhost | | ..^.#| 2025-09-30 05:00:39.272444 | controller -> localhost | | o B.EB| 2025-09-30 05:00:39.272462 | controller -> localhost | | S . + =oB| 2025-09-30 05:00:39.272481 | controller -> localhost | | . . .| 2025-09-30 05:00:39.272499 | controller -> localhost | | | 2025-09-30 05:00:39.272517 | controller -> localhost | | | 2025-09-30 05:00:39.272536 | controller -> localhost | | | 2025-09-30 05:00:39.272554 | controller -> localhost | +----[SHA256]-----+ 2025-09-30 05:00:39.272595 | controller -> localhost | ok: Runtime: 0:00:00.341474 2025-09-30 05:00:39.278239 | 2025-09-30 05:00:39.278301 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-30 05:00:39.306563 | controller | ok 2025-09-30 05:00:39.321940 | controller | included: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-30 05:00:39.353467 | 2025-09-30 05:00:39.353611 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-30 05:00:39.409126 | controller | skipping: Conditional result was False 2025-09-30 05:00:39.414616 | 2025-09-30 05:00:39.414749 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-30 05:00:39.983005 | controller | changed 2025-09-30 05:00:39.992639 | 2025-09-30 05:00:39.992780 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-30 05:00:40.285953 | controller | ok 2025-09-30 05:00:40.291873 | 2025-09-30 05:00:40.291968 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-30 05:00:41.334204 | controller | changed 2025-09-30 05:00:41.341434 | 2025-09-30 05:00:41.341524 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-30 05:00:42.392135 | controller | changed 2025-09-30 05:00:42.397057 | 2025-09-30 05:00:42.397123 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-30 05:00:42.427343 | controller | skipping: Conditional result was False 2025-09-30 05:00:42.433154 | 2025-09-30 05:00:42.433222 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-30 05:00:43.040283 | controller -> localhost | changed 2025-09-30 05:00:43.052775 | 2025-09-30 05:00:43.052875 | TASK [add-build-sshkey : Add back temp key] 2025-09-30 05:00:43.356390 | controller -> localhost | Identity added: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/work/c7fda277a9df4290be1d8efb4f621041_id_rsa (zuul-build-sshkey) 2025-09-30 05:00:43.356596 | controller -> localhost | ok: Runtime: 0:00:00.009553 2025-09-30 05:00:43.362691 | 2025-09-30 05:00:43.362774 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-30 05:00:43.906622 | controller | ok 2025-09-30 05:00:43.914807 | 2025-09-30 05:00:43.914980 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-30 05:00:43.963037 | controller | skipping: Conditional result was False 2025-09-30 05:00:43.972541 | 2025-09-30 05:00:43.972617 | TASK [include_role : validate-host] 2025-09-30 05:00:44.021870 | controller | ok 2025-09-30 05:00:44.049903 | 2025-09-30 05:00:44.050000 | TASK [validate-host : Define zuul_info_dir fact] 2025-09-30 05:00:44.079286 | controller | ok 2025-09-30 05:00:44.129061 | 2025-09-30 05:00:44.129175 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-09-30 05:00:44.496244 | controller -> localhost | ok 2025-09-30 05:00:44.502028 | 2025-09-30 05:00:44.502102 | TASK [validate-host : Collect information about the host] 2025-09-30 05:00:45.403317 | controller | ok 2025-09-30 05:00:45.412840 | 2025-09-30 05:00:45.412945 | TASK [validate-host : Sanitize hostname] 2025-09-30 05:00:45.482891 | controller | ok 2025-09-30 05:00:45.489495 | 2025-09-30 05:00:45.489620 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-09-30 05:00:46.174911 | controller -> localhost | changed 2025-09-30 05:00:46.180653 | 2025-09-30 05:00:46.180747 | TASK [validate-host : Collect information about zuul worker] 2025-09-30 05:00:46.744658 | controller | ok 2025-09-30 05:00:46.749684 | 2025-09-30 05:00:46.749763 | TASK [validate-host : Write out all zuul information for each host] 2025-09-30 05:00:47.363295 | controller -> localhost | changed 2025-09-30 05:00:47.372854 | 2025-09-30 05:00:47.372934 | TASK [include_role : prepare-workspace-openshift] 2025-09-30 05:00:47.439052 | controller | skipping: Conditional result was False 2025-09-30 05:00:47.444838 | 2025-09-30 05:00:47.444902 | TASK [include_role : remove-zuul-sshkey] 2025-09-30 05:00:47.489168 | controller | skipping: Conditional result was False 2025-09-30 05:00:47.494883 | 2025-09-30 05:00:47.494960 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-30 05:00:47.757268 | controller | ok: "logs" 2025-09-30 05:00:47.757539 | controller | ok: All items complete 2025-09-30 05:00:47.757589 | 2025-09-30 05:00:48.021771 | controller | ok: "artifacts" 2025-09-30 05:00:48.288088 | controller | ok: "docs" 2025-09-30 05:00:48.294293 | 2025-09-30 05:00:48.294374 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-30 05:00:48.585277 | controller | changed: "logs" 2025-09-30 05:00:48.873961 | controller | changed: "artifacts" 2025-09-30 05:00:49.162958 | controller | changed: "docs" 2025-09-30 05:00:49.204345 | 2025-09-30 05:00:49.204515 | PLAY RECAP 2025-09-30 05:00:49.204565 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-09-30 05:00:49.204595 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-30 05:00:49.204615 | 2025-09-30 05:00:49.322947 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-30 05:00:49.323859 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-09-30 05:00:49.912025 | 2025-09-30 05:00:49.912230 | PLAY [localhost] 2025-09-30 05:00:49.932606 | 2025-09-30 05:00:49.932764 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-09-30 05:00:50.403266 | localhost | ok 2025-09-30 05:00:50.411514 | 2025-09-30 05:00:50.411667 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-09-30 05:00:51.231072 | localhost | changed 2025-09-30 05:00:51.273812 | 2025-09-30 05:00:51.273925 | PLAY [all] 2025-09-30 05:00:51.302068 | 2025-09-30 05:00:51.302180 | TASK [include_role : prepare-workspace] 2025-09-30 05:00:51.376421 | controller | ok 2025-09-30 05:00:51.418070 | 2025-09-30 05:00:51.418195 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-30 05:00:51.900956 | controller | ok 2025-09-30 05:00:51.913915 | 2025-09-30 05:00:51.914001 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-30 05:00:54.083086 | controller | Output suppressed because no_log was given 2025-09-30 05:00:54.119196 | 2025-09-30 05:00:54.119326 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-30 05:00:54.399441 | controller | changed: "logs" 2025-09-30 05:00:54.642205 | controller | changed: "artifacts" 2025-09-30 05:00:54.891855 | controller | changed: "docs" 2025-09-30 05:00:54.904261 | 2025-09-30 05:00:54.904437 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-30 05:00:55.275945 | controller | changed: "logs" 2025-09-30 05:00:55.276162 | controller | changed: All items complete 2025-09-30 05:00:55.276189 | 2025-09-30 05:00:55.526910 | controller | changed: "artifacts" 2025-09-30 05:00:55.776979 | controller | changed: "docs" 2025-09-30 05:00:55.801896 | 2025-09-30 05:00:55.803483 | TASK [Check if worker can sudo] 2025-09-30 05:00:56.843246 | controller | ok: Runtime: 0:00:00.058154 2025-09-30 05:00:56.849231 | 2025-09-30 05:00:56.849308 | TASK [configure-mirrors : Gather needed facts] 2025-09-30 05:00:56.893983 | controller | skipping: Conditional result was False 2025-09-30 05:00:56.912046 | 2025-09-30 05:00:56.912154 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-09-30 05:00:57.104497 | controller | ok 2025-09-30 05:00:57.138892 | controller | included: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-09-30 05:00:57.144644 | 2025-09-30 05:00:57.144743 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-09-30 05:00:57.468984 | controller | ok 2025-09-30 05:00:57.474686 | 2025-09-30 05:00:57.481143 | LOOP [configure-mirrors : Include OS-specific variables] 2025-09-30 05:00:57.570383 | controller | ok: "/var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-09-30 05:00:57.583075 | 2025-09-30 05:00:57.583185 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-09-30 05:00:58.630292 | controller | changed 2025-09-30 05:00:58.635645 | 2025-09-30 05:00:58.635764 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-09-30 05:00:58.731831 | controller | ok: "/var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-09-30 05:00:58.732068 | controller | ok: All items complete 2025-09-30 05:00:58.732159 | 2025-09-30 05:00:58.800773 | controller | included: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-09-30 05:00:58.819765 | 2025-09-30 05:00:58.819878 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-09-30 05:00:59.946071 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-09-30 05:01:00.813089 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-09-30 05:01:00.824453 | 2025-09-30 05:01:00.824548 | TASK [configure-mirrors : Disable deltrarpm] 2025-09-30 05:01:01.771925 | controller | changed: section and option added 2025-09-30 05:01:01.831789 | 2025-09-30 05:01:01.831926 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-09-30 05:01:02.771933 | controller | 29 files removed 2025-09-30 05:01:02.772151 | controller | ok: Item: dnf clean all Runtime: 0:00:00.528004 2025-09-30 05:01:02.772193 | controller | changed: All items complete 2025-09-30 05:01:02.772214 | 2025-09-30 05:01:13.038035 | 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 05:01:13.038138 | controller | DNF version: 4.14.0 2025-09-30 05:01:13.038164 | controller | cachedir: /var/cache/dnf 2025-09-30 05:01:13.038196 | controller | Making cache files for all metadata files. 2025-09-30 05:01:13.038220 | controller | baseos: has expired and will be refreshed. 2025-09-30 05:01:13.038243 | controller | appstream: has expired and will be refreshed. 2025-09-30 05:01:13.038265 | controller | crb: has expired and will be refreshed. 2025-09-30 05:01:13.038325 | controller | extras-common: has expired and will be refreshed. 2025-09-30 05:01:13.038779 | controller | repo: downloading from remote: baseos 2025-09-30 05:01:13.038817 | controller | CentOS Stream 9 - BaseOS 66 MB/s | 8.8 MB 00:00 2025-09-30 05:01:13.038842 | controller | baseos: using metadata from Mon 22 Sep 2025 10:29:43 AM EDT. 2025-09-30 05:01:13.038865 | controller | repo: downloading from remote: appstream 2025-09-30 05:01:13.038888 | controller | CentOS Stream 9 - AppStream 113 MB/s | 25 MB 00:00 2025-09-30 05:01:13.038910 | controller | appstream: using metadata from Mon 22 Sep 2025 10:33:24 AM EDT. 2025-09-30 05:01:13.038932 | controller | repo: downloading from remote: crb 2025-09-30 05:01:13.038953 | controller | CentOS Stream 9 - CRB 96 MB/s | 7.1 MB 00:00 2025-09-30 05:01:13.038976 | controller | crb: using metadata from Mon 22 Sep 2025 10:37:51 AM EDT. 2025-09-30 05:01:13.038997 | controller | repo: downloading from remote: extras-common 2025-09-30 05:01:13.039019 | controller | CentOS Stream 9 - Extras packages 844 kB/s | 20 kB 00:00 2025-09-30 05:01:13.039041 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-09-30 05:01:13.039062 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-09-30 05:01:13.039083 | controller | Completion plugin: Generating completion cache... 2025-09-30 05:01:13.039103 | controller | Metadata cache created. 2025-09-30 05:01:13.039135 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.005510 2025-09-30 05:01:13.060925 | 2025-09-30 05:01:13.061025 | PLAY RECAP 2025-09-30 05:01:13.061066 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-09-30 05:01:13.061093 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-30 05:01:13.061113 | 2025-09-30 05:01:13.183026 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-09-30 05:01:13.183851 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-30 05:01:13.956950 | 2025-09-30 05:01:13.957076 | PLAY [all] 2025-09-30 05:01:13.990781 | 2025-09-30 05:01:13.990917 | TASK [Install binary dependencies] 2025-09-30 05:01:14.041373 | controller | ok 2025-09-30 05:01:14.064215 | 2025-09-30 05:01:14.064314 | TASK [bindep : Include find tasks] 2025-09-30 05:01:14.094381 | controller | ok 2025-09-30 05:01:14.102786 | controller | included: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-30 05:01:14.109827 | 2025-09-30 05:01:14.109908 | TASK [bindep : Look for bindep.txt] 2025-09-30 05:01:14.554463 | controller | ok 2025-09-30 05:01:14.568067 | 2025-09-30 05:01:14.568208 | TASK [bindep : Define bindep_file fact] 2025-09-30 05:01:14.601466 | controller | ok 2025-09-30 05:01:14.609401 | 2025-09-30 05:01:14.609492 | TASK [bindep : Look for other-requirements.txt] 2025-09-30 05:01:14.624240 | controller | skipping: Conditional result was False 2025-09-30 05:01:14.633151 | 2025-09-30 05:01:14.633269 | TASK [bindep : Define bindep_file fact] 2025-09-30 05:01:14.662954 | controller | skipping: Conditional result was False 2025-09-30 05:01:14.673795 | 2025-09-30 05:01:14.673899 | TASK [bindep : Look for bindep fallback file] 2025-09-30 05:01:14.708869 | controller | skipping: Conditional result was False 2025-09-30 05:01:14.717657 | 2025-09-30 05:01:14.717780 | TASK [bindep : Define bindep_file fact] 2025-09-30 05:01:14.743113 | controller | skipping: Conditional result was False 2025-09-30 05:01:14.752191 | 2025-09-30 05:01:14.752438 | TASK [bindep : Include bindep tasks] 2025-09-30 05:01:14.787065 | controller | ok 2025-09-30 05:01:14.797790 | controller | included: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-09-30 05:01:14.810625 | 2025-09-30 05:01:14.810780 | TASK [bindep : Look for bindep command] 2025-09-30 05:01:14.836792 | controller | skipping: Conditional result was False 2025-09-30 05:01:14.843656 | 2025-09-30 05:01:14.843749 | TASK [bindep : Check for system bindep] 2025-09-30 05:01:15.380982 | controller | ok: Runtime: 0:00:00.011698 2025-09-30 05:01:15.389232 | 2025-09-30 05:01:15.389360 | TASK [bindep : Define bindep_command fact] 2025-09-30 05:01:15.417461 | controller | skipping: Conditional result was False 2025-09-30 05:01:15.426367 | 2025-09-30 05:01:15.426475 | TASK [bindep : Include install tasks] 2025-09-30 05:01:15.462952 | controller | ok 2025-09-30 05:01:15.474380 | controller | included: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-09-30 05:01:15.488054 | 2025-09-30 05:01:15.488195 | TASK [bindep : Create temp dir for bindep] 2025-09-30 05:01:15.885060 | controller | changed 2025-09-30 05:01:15.899032 | 2025-09-30 05:01:15.899219 | TASK [Ensure we have pip dependencies] 2025-09-30 05:01:15.941246 | controller | ok 2025-09-30 05:01:15.977589 | 2025-09-30 05:01:15.977702 | TASK [ensure-pip : Check if pip is installed] 2025-09-30 01:01:16.242381 | controller | /usr/bin/pip3 2025-09-30 01:01:16.262444 | controller | /usr/bin/python3: No module named wheel 2025-09-30 05:01:16.512280 | controller | ok: Runtime: 0:00:00.028967 2025-09-30 05:01:16.525464 | 2025-09-30 05:01:16.525636 | LOOP [ensure-pip : Install pip from packages] 2025-09-30 05:01:16.584986 | controller | ok: "/var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-09-30 05:01:16.607143 | controller | included: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-09-30 05:01:16.622033 | 2025-09-30 05:01:16.622159 | TASK [ensure-pip : Install Python 3 pip] 2025-09-30 05:01:19.029240 | controller | changed 2025-09-30 05:01:19.035377 | 2025-09-30 05:01:19.035484 | TASK [ensure-pip : Check for EPEL repository] 2025-09-30 05:01:19.085043 | controller | skipping: Conditional result was False 2025-09-30 05:01:19.092530 | 2025-09-30 05:01:19.092644 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-09-30 05:01:19.168233 | controller | skipping: Conditional result was False 2025-09-30 05:01:19.174967 | 2025-09-30 05:01:19.175039 | TASK [ensure-pip : Install Python 2 pip] 2025-09-30 05:01:19.222320 | controller | skipping: Conditional result was False 2025-09-30 05:01:19.229651 | 2025-09-30 05:01:19.229718 | TASK [ensure-pip : Ensure setuptools] 2025-09-30 05:01:19.277139 | controller | skipping: Conditional result was False 2025-09-30 05:01:19.285942 | 2025-09-30 05:01:19.286039 | TASK [ensure-pip : Check for ensurepip module] 2025-09-30 05:01:19.844966 | controller | skipping: Conditional result was False 2025-09-30 05:01:19.859363 | 2025-09-30 05:01:19.859476 | TASK [ensure-pip : Ensure python3-venv] 2025-09-30 05:01:19.883835 | controller | skipping: Conditional result was False 2025-09-30 05:01:19.889676 | 2025-09-30 05:01:19.889786 | TASK [ensure-pip : Install pip from source] 2025-09-30 05:01:19.924256 | controller | skipping: Conditional result was False 2025-09-30 05:01:19.930049 | 2025-09-30 05:01:19.930156 | TASK [ensure-pip : Probe for venv python full path] 2025-09-30 01:01:20.222707 | controller | /usr/bin/python3 2025-09-30 05:01:20.480619 | controller | ok: Runtime: 0:00:00.009105 2025-09-30 05:01:20.486313 | 2025-09-30 05:01:20.486376 | TASK [ensure-pip : Set host default] 2025-09-30 05:01:20.567131 | controller | ok 2025-09-30 05:01:20.572113 | 2025-09-30 05:01:20.572174 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-09-30 05:01:20.654662 | controller | ok 2025-09-30 05:01:20.665569 | 2025-09-30 05:01:20.665646 | TASK [bindep : Install bindep into temporary venv] 2025-09-30 05:01:24.713554 | controller | changed 2025-09-30 05:01:24.718988 | 2025-09-30 05:01:24.719060 | TASK [bindep : Define bindep_command] 2025-09-30 05:01:24.749526 | controller | ok 2025-09-30 05:01:24.755079 | 2025-09-30 05:01:24.755150 | LOOP [bindep : Include package tasks] 2025-09-30 05:01:24.820895 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-09-30 05:01:24.821080 | controller | ok: All items complete 2025-09-30 05:01:24.821107 | 2025-09-30 05:01:24.830174 | controller | included: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-09-30 05:01:24.841259 | 2025-09-30 05:01:24.841329 | TASK [bindep : Define bindep_run fact] 2025-09-30 05:01:24.881433 | controller | ok 2025-09-30 05:01:24.886667 | 2025-09-30 05:01:24.886737 | TASK [bindep : Get list of packages to install from bindep] 2025-09-30 01:01:26.398211 | controller | podman 2025-09-30 01:01:26.450971 | controller | python3-jmespath 2025-09-30 01:01:26.451260 | controller | python3-libvirt 2025-09-30 01:01:26.451278 | controller | python3-lxml 2025-09-30 01:01:26.451289 | controller | python3-netaddr 2025-09-30 05:01:26.925245 | controller | ok: Runtime: 0:00:01.229304 2025-09-30 05:01:26.934507 | 2025-09-30 05:01:26.934612 | TASK [bindep : Install distro packages from bindep] 2025-09-30 05:02:28.587151 | controller | changed 2025-09-30 05:02:28.593518 | 2025-09-30 05:02:28.593621 | TASK [bindep : Check that packages are installed] 2025-09-30 05:02:30.125763 | controller | ok: Runtime: 0:00:01.077980 2025-09-30 05:02:30.138311 | 2025-09-30 05:02:30.138458 | TASK [bindep : Fail if we cannot install all packages] 2025-09-30 05:02:30.176855 | controller | skipping: Conditional result was False 2025-09-30 05:02:30.202721 | 2025-09-30 05:02:30.202978 | TASK [Run test-setup role] 2025-09-30 05:02:30.230229 | controller | ok 2025-09-30 05:02:30.255827 | 2025-09-30 05:02:30.256000 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-30 05:02:30.502864 | controller | ok 2025-09-30 05:02:30.508191 | 2025-09-30 05:02:30.508263 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-30 05:02:31.039094 | controller | skipping: Conditional result was False 2025-09-30 05:02:31.066072 | 2025-09-30 05:02:31.066174 | TASK [bindep : Remove bindep temp dir] 2025-09-30 05:02:31.402224 | controller | ok 2025-09-30 05:02:31.426877 | 2025-09-30 05:02:31.426990 | PLAY RECAP 2025-09-30 05:02:31.427051 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-09-30 05:02:31.427086 | 2025-09-30 05:02:31.536857 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-30 05:02:31.538139 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-09-30 05:02:32.137656 | 2025-09-30 05:02:32.137880 | PLAY [all] 2025-09-30 05:02:32.158685 | 2025-09-30 05:02:32.158829 | TASK [Abort when test_command variable is undefined] 2025-09-30 05:02:32.194227 | controller | skipping: Conditional result was False 2025-09-30 05:02:32.200518 | 2025-09-30 05:02:32.200603 | TASK [Convert test_command to list] 2025-09-30 05:02:32.256185 | controller | skipping: Conditional result was False 2025-09-30 05:02:32.265770 | 2025-09-30 05:02:32.265880 | TASK [Use test_command list] 2025-09-30 05:02:32.334118 | controller | ok 2025-09-30 05:02:32.347156 | 2025-09-30 05:02:32.347320 | LOOP [Run test_command] 2025-09-30 05:02:32.727983 | controller | no check to run 2025-09-30 05:02:32.728182 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.007324 2025-09-30 05:02:32.778398 | 2025-09-30 05:02:32.778549 | PLAY RECAP 2025-09-30 05:02:32.778627 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-09-30 05:02:32.778671 | 2025-09-30 05:02:32.893910 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-09-30 05:02:32.895116 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-30 05:02:33.505644 | 2025-09-30 05:02:33.505780 | PLAY [all] 2025-09-30 05:02:33.526378 | 2025-09-30 05:02:33.526495 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-30 05:02:33.905909 | controller | changed: non-zero return code 2025-09-30 05:02:33.914143 | 2025-09-30 05:02:33.914279 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-30 05:02:33.930002 | controller | skipping: Conditional result was False 2025-09-30 05:02:33.939754 | 2025-09-30 05:02:33.939917 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-30 05:02:33.964844 | 2025-09-30 05:02:33.965096 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-30 05:02:33.989429 | 2025-09-30 05:02:33.989644 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-30 05:02:34.005145 | controller | skipping: Conditional result was False 2025-09-30 05:02:34.014079 | 2025-09-30 05:02:34.014183 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-30 05:02:34.037997 | 2025-09-30 05:02:34.038196 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-30 05:02:34.053629 | controller | skipping: Conditional result was False 2025-09-30 05:02:34.063631 | 2025-09-30 05:02:34.063721 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-30 05:02:34.078354 | controller | skipping: Conditional result was False 2025-09-30 05:02:34.086313 | 2025-09-30 05:02:34.086401 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-30 05:02:34.111543 | controller | skipping: Conditional result was False 2025-09-30 05:02:34.157484 | 2025-09-30 05:02:34.157609 | PLAY RECAP 2025-09-30 05:02:34.157686 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-30 05:02:34.157763 | 2025-09-30 05:02:34.270896 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-30 05:02:34.271746 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-30 05:02:34.998835 | 2025-09-30 05:02:34.998943 | PLAY [all] 2025-09-30 05:02:35.035194 | 2025-09-30 05:02:35.035303 | TASK [include_role : fetch-output] 2025-09-30 05:02:35.074959 | controller | ok 2025-09-30 05:02:35.092609 | 2025-09-30 05:02:35.092698 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-30 05:02:35.137134 | controller | skipping: Conditional result was False 2025-09-30 05:02:35.142700 | 2025-09-30 05:02:35.142853 | TASK [fetch-output : Set log path for single node] 2025-09-30 05:02:35.174478 | controller | ok 2025-09-30 05:02:35.182134 | 2025-09-30 05:02:35.182234 | LOOP [fetch-output : Ensure local output dirs] 2025-09-30 05:02:35.605153 | controller -> localhost | ok: "/var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/work/logs" 2025-09-30 05:02:35.800127 | controller -> localhost | changed: "/var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/work/artifacts" 2025-09-30 05:02:35.997301 | controller -> localhost | changed: "/var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/work/docs" 2025-09-30 05:02:36.010381 | 2025-09-30 05:02:36.010530 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-30 05:02:36.652373 | controller | changed: .d..t...... ./ 2025-09-30 05:02:36.657977 | controller | changed: All items complete 2025-09-30 05:02:36.658085 | 2025-09-30 05:02:37.124707 | controller | changed: .d..t...... ./ 2025-09-30 05:02:37.573496 | controller | changed: .d..t...... ./ 2025-09-30 05:02:37.595536 | 2025-09-30 05:02:37.595639 | TASK [include_role : fetch-output-openshift] 2025-09-30 05:02:37.619657 | controller | skipping: Conditional result was False 2025-09-30 05:02:37.626455 | 2025-09-30 05:02:37.626539 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-30 05:02:38.029958 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.012863 2025-09-30 05:02:38.291112 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.010003 2025-09-30 05:02:38.323658 | 2025-09-30 05:02:38.323815 | PLAY [all] 2025-09-30 05:02:38.342542 | 2025-09-30 05:02:38.342609 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-09-30 05:02:38.907665 | controller | changed 2025-09-30 05:02:38.941209 | 2025-09-30 05:02:38.941324 | PLAY RECAP 2025-09-30 05:02:38.941379 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-09-30 05:02:38.941409 | 2025-09-30 05:02:39.034716 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-30 05:02:39.035752 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-09-30 05:02:39.661327 | 2025-09-30 05:02:39.661464 | PLAY [localhost] 2025-09-30 05:02:39.681775 | 2025-09-30 05:02:39.681912 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-30 05:02:40.062606 | localhost | changed 2025-09-30 05:02:40.073649 | 2025-09-30 05:02:40.073850 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-30 05:02:40.105618 | localhost | ok 2025-09-30 05:02:40.117365 | 2025-09-30 05:02:40.117461 | TASK [add-fileserver : Create SSH private key tempfile] 2025-09-30 05:02:40.505404 | localhost | changed 2025-09-30 05:02:40.511368 | 2025-09-30 05:02:40.511450 | TASK [add-fileserver : Create SSH private key from secret] 2025-09-30 05:02:41.139040 | localhost | changed 2025-09-30 05:02:41.144223 | 2025-09-30 05:02:41.144309 | TASK [add-fileserver : Add fileserver ssh key] 2025-09-30 05:02:41.572811 | localhost | Identity added: /var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/work/tmp/ansible.b_qj6_ko (/var/lib/zuul/builds/c7fda277a9df4290be1d8efb4f621041/work/tmp/ansible.b_qj6_ko) 2025-09-30 05:02:41.572979 | localhost | ok: Runtime: 0:00:00.007412 2025-09-30 05:02:41.578128 | 2025-09-30 05:02:41.578198 | TASK [add-fileserver : Remove SSH private key from disk] 2025-09-30 05:02:41.857800 | localhost | ok: Runtime: 0:00:00.007845 2025-09-30 05:02:41.862544 | 2025-09-30 05:02:41.862611 | TASK [add-fileserver : Add fileserver to inventory] 2025-09-30 05:02:41.921359 | localhost | changed 2025-09-30 05:02:41.925637 | 2025-09-30 05:02:41.925700 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-09-30 05:02:42.287957 | localhost | changed 2025-09-30 05:02:42.308933 | 2025-09-30 05:02:42.308997 | PLAY [localhost] 2025-09-30 05:02:42.321192 | 2025-09-30 05:02:42.321253 | TASK [Generate bulk log download script] 2025-09-30 05:02:42.339923 | localhost | ok 2025-09-30 05:02:42.351104 | 2025-09-30 05:02:42.351169 | TASK [local-log-download : Check API endpoint is defined] 2025-09-30 05:02:42.378218 | localhost | ok: All assertions passed 2025-09-30 05:02:42.382674 | 2025-09-30 05:02:42.382782 | TASK [local-log-download : Create download script] 2025-09-30 05:02:42.753268 | localhost -> localhost | changed 2025-09-30 05:02:42.761933 | 2025-09-30 05:02:42.761997 | TASK [Register quick-download link] 2025-09-30 05:02:42.779354 | localhost | ok 2025-09-30 05:02:42.818998 | 2025-09-30 05:02:42.819095 | PLAY [logserver.rdoproject.org] 2025-09-30 05:02:42.828248 | 2025-09-30 05:02:42.828304 | TASK [Set zuul-log-path fact] 2025-09-30 05:02:42.844202 | logserver.rdoproject.org | ok 2025-09-30 05:02:42.852827 | 2025-09-30 05:02:42.852891 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-30 05:02:42.878213 | logserver.rdoproject.org | ok 2025-09-30 05:02:42.883390 | 2025-09-30 05:02:42.883449 | TASK [upload-logs : Create log directories] 2025-09-30 05:02:43.595218 | logserver.rdoproject.org | changed 2025-09-30 05:02:43.598416 | 2025-09-30 05:02:43.598498 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-09-30 05:02:43.898652 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.006081 2025-09-30 05:02:43.904160 | 2025-09-30 05:02:43.904257 | TASK [upload-logs : Upload logs to log server] 2025-09-30 05:02:44.636460 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-09-30 05:02:44.643967 | 2025-09-30 05:02:44.644123 | LOOP [upload-logs : Compress console log and json output] 2025-09-30 05:02:44.710449 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 05:02:44.723791 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 05:02:44.736607 | 2025-09-30 05:02:44.736767 | LOOP [upload-logs : Upload compressed console log and json output] 2025-09-30 05:02:44.776038 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 05:02:44.776278 | 2025-09-30 05:02:44.779622 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 05:02:44.787645 | 2025-09-30 05:02:44.787777 | LOOP [upload-logs : Upload console log and json output]