2025-10-13 06:53:37.759049 | Job console starting... 2025-10-13 06:53:37.767752 | Updating repositories 2025-10-13 06:53:37.796129 | Preparing job workspace 2025-10-13 06:53:41.342356 | Running Ansible setup... 2025-10-13 06:53:45.393085 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-13 06:53:46.091342 | 2025-10-13 06:53:46.091470 | PLAY [localhost] 2025-10-13 06:53:46.103384 | 2025-10-13 06:53:46.103519 | TASK [Gathering Facts] 2025-10-13 06:53:47.467189 | localhost | ok 2025-10-13 06:53:47.481680 | 2025-10-13 06:53:47.481793 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-13 06:53:47.995533 | localhost -> localhost | changed 2025-10-13 06:53:48.019544 | 2025-10-13 06:53:48.019650 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-13 06:53:49.291475 | localhost -> localhost | changed 2025-10-13 06:53:49.301706 | 2025-10-13 06:53:49.301775 | TASK [Setup log path fact] 2025-10-13 06:53:49.350358 | localhost | ok 2025-10-13 06:53:49.364575 | 2025-10-13 06:53:49.364750 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-13 06:53:49.398598 | localhost | ok 2025-10-13 06:53:49.407734 | 2025-10-13 06:53:49.407803 | TASK [emit-job-header : Print job information] 2025-10-13 06:53:49.446212 | # Job Information 2025-10-13 06:53:49.446391 | Ansible Version: 2.15.12 2025-10-13 06:53:49.446418 | Job: cifmw-molecule-ovirt 2025-10-13 06:53:49.446438 | Pipeline: github-check 2025-10-13 06:53:49.446455 | Executor: ze01.softwarefactory-project.io 2025-10-13 06:53:49.446473 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3237 2025-10-13 06:53:49.446491 | Log URL (when completed): https://logserver.rdoproject.org/573/rdoproject.org/573f27c61c0144fcba702b04032aca6c/ 2025-10-13 06:53:49.446508 | Event ID: 0a621880-a801-11f0-8fd5-3020d4b2b2c2 2025-10-13 06:53:49.450525 | 2025-10-13 06:53:49.450592 | LOOP [emit-job-header : Print node information] 2025-10-13 06:53:49.562281 | localhost | ok: 2025-10-13 06:53:49.562452 | localhost | # Node Information 2025-10-13 06:53:49.562478 | localhost | Inventory Hostname: controller 2025-10-13 06:53:49.562504 | localhost | Hostname: np0005482622 2025-10-13 06:53:49.562665 | localhost | Username: zuul 2025-10-13 06:53:49.562703 | localhost | Distro: CentOS 9 2025-10-13 06:53:49.562723 | localhost | Provider: vexxhost-nodepool-tripleo 2025-10-13 06:53:49.562742 | localhost | Region: RegionOne 2025-10-13 06:53:49.562760 | localhost | Label: cloud-centos-9-stream-tripleo 2025-10-13 06:53:49.562777 | localhost | Product Name: OpenStack Nova 2025-10-13 06:53:49.562794 | localhost | Interface IP: 38.129.56.147 2025-10-13 06:53:49.584331 | 2025-10-13 06:53:49.584422 | PLAY [all] 2025-10-13 06:53:49.591755 | 2025-10-13 06:53:49.591830 | TASK [Gather network facts] 2025-10-13 06:53:51.073249 | controller | ok 2025-10-13 06:53:51.099066 | 2025-10-13 06:53:51.099236 | TASK [include_role : start-zuul-console] 2025-10-13 06:53:51.122237 | controller | ok 2025-10-13 06:53:51.161951 | 2025-10-13 06:53:51.162099 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-13 06:53:51.738644 | controller | ok 2025-10-13 06:53:51.749946 | 2025-10-13 06:53:51.750018 | TASK [include_role : add-build-sshkey] 2025-10-13 06:53:51.802600 | controller | ok 2025-10-13 06:53:51.825246 | 2025-10-13 06:53:51.825384 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-13 06:53:52.689610 | controller -> localhost | ok 2025-10-13 06:53:52.695992 | 2025-10-13 06:53:52.696080 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-13 06:53:52.732133 | controller | ok 2025-10-13 06:53:52.757404 | controller | included: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-13 06:53:52.767861 | 2025-10-13 06:53:52.767941 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-13 06:53:53.496424 | controller -> localhost | Generating public/private rsa key pair. 2025-10-13 06:53:53.496647 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/work/573f27c61c0144fcba702b04032aca6c_id_rsa. 2025-10-13 06:53:53.496678 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/work/573f27c61c0144fcba702b04032aca6c_id_rsa.pub. 2025-10-13 06:53:53.496700 | controller -> localhost | The key fingerprint is: 2025-10-13 06:53:53.496720 | controller -> localhost | SHA256:9fHR+/2w8gA9Vc6XKNndxPmZOPvasRCxWuJ3ReyUdS0 zuul-build-sshkey 2025-10-13 06:53:53.496739 | controller -> localhost | The key's randomart image is: 2025-10-13 06:53:53.496758 | controller -> localhost | +---[RSA 3072]----+ 2025-10-13 06:53:53.496775 | controller -> localhost | | .B| 2025-10-13 06:53:53.496793 | controller -> localhost | | o EOO| 2025-10-13 06:53:53.496811 | controller -> localhost | | .o.++=&| 2025-10-13 06:53:53.496828 | controller -> localhost | | . o.*oB+| 2025-10-13 06:53:53.496846 | controller -> localhost | | S ..+++.o| 2025-10-13 06:53:53.496863 | controller -> localhost | | ..+o. +| 2025-10-13 06:53:53.496879 | controller -> localhost | | o.oooo| 2025-10-13 06:53:53.496896 | controller -> localhost | | o.+++| 2025-10-13 06:53:53.496913 | controller -> localhost | | ++o.| 2025-10-13 06:53:53.496929 | controller -> localhost | +----[SHA256]-----+ 2025-10-13 06:53:53.496971 | controller -> localhost | ok: Runtime: 0:00:00.199961 2025-10-13 06:53:53.502793 | 2025-10-13 06:53:53.502861 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-13 06:53:53.543335 | controller | ok 2025-10-13 06:53:53.559589 | controller | included: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-13 06:53:53.570724 | 2025-10-13 06:53:53.570788 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-13 06:53:53.594621 | controller | skipping: Conditional result was False 2025-10-13 06:53:53.601093 | 2025-10-13 06:53:53.601161 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-13 06:53:54.105690 | controller | changed 2025-10-13 06:53:54.113779 | 2025-10-13 06:53:54.113865 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-13 06:53:54.413340 | controller | ok 2025-10-13 06:53:54.419337 | 2025-10-13 06:53:54.419417 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-13 06:53:55.302941 | controller | changed 2025-10-13 06:53:55.309178 | 2025-10-13 06:53:55.309346 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-13 06:53:56.182268 | controller | changed 2025-10-13 06:53:56.189615 | 2025-10-13 06:53:56.189713 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-13 06:53:56.221503 | controller | skipping: Conditional result was False 2025-10-13 06:53:56.233244 | 2025-10-13 06:53:56.233384 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-13 06:53:56.585827 | controller -> localhost | changed 2025-10-13 06:53:56.596043 | 2025-10-13 06:53:56.596119 | TASK [add-build-sshkey : Add back temp key] 2025-10-13 06:53:56.877810 | controller -> localhost | Identity added: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/work/573f27c61c0144fcba702b04032aca6c_id_rsa (zuul-build-sshkey) 2025-10-13 06:53:56.878000 | controller -> localhost | ok: Runtime: 0:00:00.031515 2025-10-13 06:53:56.883773 | 2025-10-13 06:53:56.883835 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-13 06:53:57.272554 | controller | ok 2025-10-13 06:53:57.278710 | 2025-10-13 06:53:57.278806 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-13 06:53:57.303606 | controller | skipping: Conditional result was False 2025-10-13 06:53:57.313822 | 2025-10-13 06:53:57.313910 | TASK [include_role : validate-host] 2025-10-13 06:53:57.343383 | controller | ok 2025-10-13 06:53:57.402065 | 2025-10-13 06:53:57.402191 | TASK [validate-host : Define zuul_info_dir fact] 2025-10-13 06:53:57.431665 | controller | ok 2025-10-13 06:53:57.436812 | 2025-10-13 06:53:57.436878 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-10-13 06:53:57.727264 | controller -> localhost | ok 2025-10-13 06:53:57.735306 | 2025-10-13 06:53:57.735414 | TASK [validate-host : Collect information about the host] 2025-10-13 06:53:58.525682 | controller | ok 2025-10-13 06:53:58.536075 | 2025-10-13 06:53:58.536179 | TASK [validate-host : Sanitize hostname] 2025-10-13 06:53:58.585681 | controller | ok 2025-10-13 06:53:58.590725 | 2025-10-13 06:53:58.590786 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-10-13 06:53:59.056946 | controller -> localhost | changed 2025-10-13 06:53:59.064302 | 2025-10-13 06:53:59.064393 | TASK [validate-host : Collect information about zuul worker] 2025-10-13 06:53:59.482887 | controller | ok 2025-10-13 06:53:59.488379 | 2025-10-13 06:53:59.488487 | TASK [validate-host : Write out all zuul information for each host] 2025-10-13 06:54:00.135766 | controller -> localhost | changed 2025-10-13 06:54:00.152483 | 2025-10-13 06:54:00.152587 | TASK [include_role : prepare-workspace-openshift] 2025-10-13 06:54:00.198892 | controller | skipping: Conditional result was False 2025-10-13 06:54:00.206202 | 2025-10-13 06:54:00.206282 | TASK [include_role : remove-zuul-sshkey] 2025-10-13 06:54:00.250352 | controller | skipping: Conditional result was False 2025-10-13 06:54:00.256497 | 2025-10-13 06:54:00.256580 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-13 06:54:00.562317 | controller | ok: "logs" 2025-10-13 06:54:00.562633 | controller | ok: All items complete 2025-10-13 06:54:00.562662 | 2025-10-13 06:54:00.801204 | controller | ok: "artifacts" 2025-10-13 06:54:01.047465 | controller | ok: "docs" 2025-10-13 06:54:01.061725 | 2025-10-13 06:54:01.061865 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-13 06:54:01.376343 | controller | changed: "logs" 2025-10-13 06:54:01.594698 | controller | changed: "artifacts" 2025-10-13 06:54:01.851455 | controller | changed: "docs" 2025-10-13 06:54:01.881386 | 2025-10-13 06:54:01.881487 | PLAY RECAP 2025-10-13 06:54:01.881529 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-13 06:54:01.881554 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-13 06:54:01.881572 | 2025-10-13 06:54:02.001775 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-13 06:54:02.002603 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-13 06:54:02.732184 | 2025-10-13 06:54:02.732298 | PLAY [localhost] 2025-10-13 06:54:02.754433 | 2025-10-13 06:54:02.754574 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-10-13 06:54:03.185443 | localhost | ok 2025-10-13 06:54:03.190911 | 2025-10-13 06:54:03.191037 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-10-13 06:54:04.038531 | localhost | changed 2025-10-13 06:54:04.088048 | 2025-10-13 06:54:04.088160 | PLAY [all] 2025-10-13 06:54:04.116343 | 2025-10-13 06:54:04.116455 | TASK [include_role : prepare-workspace] 2025-10-13 06:54:04.156275 | controller | ok 2025-10-13 06:54:04.170851 | 2025-10-13 06:54:04.170924 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-13 06:54:04.619293 | controller | ok 2025-10-13 06:54:04.627459 | 2025-10-13 06:54:04.627594 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-13 06:54:06.366965 | controller | Output suppressed because no_log was given 2025-10-13 06:54:06.386838 | 2025-10-13 06:54:06.386935 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-13 06:54:06.686657 | controller | changed: "logs" 2025-10-13 06:54:06.911525 | controller | changed: "artifacts" 2025-10-13 06:54:07.130273 | controller | changed: "docs" 2025-10-13 06:54:07.145990 | 2025-10-13 06:54:07.146115 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-13 06:54:07.416525 | controller | changed: "logs" 2025-10-13 06:54:07.416827 | controller | changed: All items complete 2025-10-13 06:54:07.416967 | 2025-10-13 06:54:07.677064 | controller | changed: "artifacts" 2025-10-13 06:54:07.901884 | controller | changed: "docs" 2025-10-13 06:54:07.929901 | 2025-10-13 06:54:07.930093 | TASK [Check if worker can sudo] 2025-10-13 06:54:08.467258 | controller | ok: Runtime: 0:00:00.069406 2025-10-13 06:54:08.474980 | 2025-10-13 06:54:08.475086 | TASK [configure-mirrors : Gather needed facts] 2025-10-13 06:54:08.532074 | controller | skipping: Conditional result was False 2025-10-13 06:54:08.538081 | 2025-10-13 06:54:08.538146 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-10-13 06:54:08.638098 | controller | ok 2025-10-13 06:54:08.646746 | controller | included: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-10-13 06:54:08.653303 | 2025-10-13 06:54:08.653361 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-10-13 06:54:08.986627 | controller | ok 2025-10-13 06:54:09.022828 | 2025-10-13 06:54:09.022941 | LOOP [configure-mirrors : Include OS-specific variables] 2025-10-13 06:54:09.146004 | controller | ok: "/var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-10-13 06:54:09.159659 | 2025-10-13 06:54:09.159780 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-10-13 06:54:10.051093 | controller | changed 2025-10-13 06:54:10.056718 | 2025-10-13 06:54:10.056780 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-10-13 06:54:10.107217 | controller | ok: "/var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-10-13 06:54:10.107504 | controller | ok: All items complete 2025-10-13 06:54:10.107538 | 2025-10-13 06:54:10.176402 | controller | included: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-10-13 06:54:10.183141 | 2025-10-13 06:54:10.183204 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-10-13 06:54:11.114590 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-10-13 06:54:11.945538 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-10-13 06:54:11.955170 | 2025-10-13 06:54:11.955303 | TASK [configure-mirrors : Disable deltrarpm] 2025-10-13 06:54:12.466904 | controller | changed: section and option added 2025-10-13 06:54:12.492648 | 2025-10-13 06:54:12.492871 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-10-13 06:54:13.423277 | controller | 29 files removed 2025-10-13 06:54:13.423498 | controller | ok: Item: dnf clean all Runtime: 0:00:00.500693 2025-10-13 06:54:13.423539 | controller | changed: All items complete 2025-10-13 06:54:13.423561 | 2025-10-13 06:54:24.745733 | 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-13 06:54:24.745847 | controller | DNF version: 4.14.0 2025-10-13 06:54:24.745873 | controller | cachedir: /var/cache/dnf 2025-10-13 06:54:24.745893 | controller | Making cache files for all metadata files. 2025-10-13 06:54:24.745913 | controller | baseos: has expired and will be refreshed. 2025-10-13 06:54:24.745933 | controller | appstream: has expired and will be refreshed. 2025-10-13 06:54:24.745953 | controller | crb: has expired and will be refreshed. 2025-10-13 06:54:24.745985 | controller | extras-common: has expired and will be refreshed. 2025-10-13 06:54:24.746002 | controller | repo: downloading from remote: baseos 2025-10-13 06:54:24.746050 | controller | CentOS Stream 9 - BaseOS 68 MB/s | 8.8 MB 00:00 2025-10-13 06:54:24.746070 | controller | baseos: using metadata from Wed 08 Oct 2025 09:42:12 AM EDT. 2025-10-13 06:54:24.746087 | controller | repo: downloading from remote: appstream 2025-10-13 06:54:24.746104 | controller | CentOS Stream 9 - AppStream 70 MB/s | 25 MB 00:00 2025-10-13 06:54:24.746120 | controller | appstream: using metadata from Wed 08 Oct 2025 09:45:45 AM EDT. 2025-10-13 06:54:24.746136 | controller | repo: downloading from remote: crb 2025-10-13 06:54:24.746152 | controller | CentOS Stream 9 - CRB 73 MB/s | 7.2 MB 00:00 2025-10-13 06:54:24.746169 | controller | crb: using metadata from Wed 08 Oct 2025 09:50:07 AM EDT. 2025-10-13 06:54:24.746185 | controller | repo: downloading from remote: extras-common 2025-10-13 06:54:24.746202 | controller | CentOS Stream 9 - Extras packages 1.6 MB/s | 20 kB 00:00 2025-10-13 06:54:24.746218 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-10-13 06:54:24.746235 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-10-13 06:54:24.746251 | controller | Completion plugin: Generating completion cache... 2025-10-13 06:54:24.746267 | controller | Metadata cache created. 2025-10-13 06:54:24.746293 | controller | ok: Item: dnf makecache -v Runtime: 0:00:11.048702 2025-10-13 06:54:24.761751 | 2025-10-13 06:54:24.761866 | PLAY RECAP 2025-10-13 06:54:24.761913 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-13 06:54:24.761939 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-13 06:54:24.761956 | 2025-10-13 06:54:24.934539 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-13 06:54:24.935395 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-13 06:54:25.592314 | 2025-10-13 06:54:25.592452 | PLAY [all] 2025-10-13 06:54:25.613924 | 2025-10-13 06:54:25.614079 | TASK [Install binary dependencies] 2025-10-13 06:54:25.696323 | controller | ok 2025-10-13 06:54:25.717773 | 2025-10-13 06:54:25.717918 | TASK [bindep : Include find tasks] 2025-10-13 06:54:25.747341 | controller | ok 2025-10-13 06:54:25.754993 | controller | included: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-13 06:54:25.760923 | 2025-10-13 06:54:25.760989 | TASK [bindep : Look for bindep.txt] 2025-10-13 06:54:26.187652 | controller | ok 2025-10-13 06:54:26.201626 | 2025-10-13 06:54:26.201807 | TASK [bindep : Define bindep_file fact] 2025-10-13 06:54:26.244847 | controller | ok 2025-10-13 06:54:26.252282 | 2025-10-13 06:54:26.252377 | TASK [bindep : Look for other-requirements.txt] 2025-10-13 06:54:26.278226 | controller | skipping: Conditional result was False 2025-10-13 06:54:26.286699 | 2025-10-13 06:54:26.286842 | TASK [bindep : Define bindep_file fact] 2025-10-13 06:54:26.326870 | controller | skipping: Conditional result was False 2025-10-13 06:54:26.335595 | 2025-10-13 06:54:26.335698 | TASK [bindep : Look for bindep fallback file] 2025-10-13 06:54:26.361510 | controller | skipping: Conditional result was False 2025-10-13 06:54:26.370421 | 2025-10-13 06:54:26.370584 | TASK [bindep : Define bindep_file fact] 2025-10-13 06:54:26.395671 | controller | skipping: Conditional result was False 2025-10-13 06:54:26.404135 | 2025-10-13 06:54:26.404265 | TASK [bindep : Include bindep tasks] 2025-10-13 06:54:26.439163 | controller | ok 2025-10-13 06:54:26.448563 | controller | included: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-10-13 06:54:26.460455 | 2025-10-13 06:54:26.460591 | TASK [bindep : Look for bindep command] 2025-10-13 06:54:26.486214 | controller | skipping: Conditional result was False 2025-10-13 06:54:26.495492 | 2025-10-13 06:54:26.495619 | TASK [bindep : Check for system bindep] 2025-10-13 06:54:27.037871 | controller | ok: Runtime: 0:00:00.005410 2025-10-13 06:54:27.045087 | 2025-10-13 06:54:27.045209 | TASK [bindep : Define bindep_command fact] 2025-10-13 06:54:27.072939 | controller | skipping: Conditional result was False 2025-10-13 06:54:27.079036 | 2025-10-13 06:54:27.079137 | TASK [bindep : Include install tasks] 2025-10-13 06:54:27.109120 | controller | ok 2025-10-13 06:54:27.116910 | controller | included: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-10-13 06:54:27.127375 | 2025-10-13 06:54:27.127483 | TASK [bindep : Create temp dir for bindep] 2025-10-13 06:54:27.523842 | controller | changed 2025-10-13 06:54:27.535671 | 2025-10-13 06:54:27.535839 | TASK [Ensure we have pip dependencies] 2025-10-13 06:54:27.568130 | controller | ok 2025-10-13 06:54:27.613993 | 2025-10-13 06:54:27.614162 | TASK [ensure-pip : Check if pip is installed] 2025-10-13 02:54:27.899834 | controller | /usr/bin/pip3 2025-10-13 02:54:27.922245 | controller | /usr/bin/python3: No module named wheel 2025-10-13 06:54:28.155194 | controller | ok: Runtime: 0:00:00.032954 2025-10-13 06:54:28.165269 | 2025-10-13 06:54:28.165359 | LOOP [ensure-pip : Install pip from packages] 2025-10-13 06:54:28.194704 | controller | ok: "/var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-10-13 06:54:28.208070 | controller | included: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-10-13 06:54:28.218601 | 2025-10-13 06:54:28.218672 | TASK [ensure-pip : Install Python 3 pip] 2025-10-13 06:54:30.557855 | controller | changed 2025-10-13 06:54:30.563146 | 2025-10-13 06:54:30.563213 | TASK [ensure-pip : Check for EPEL repository] 2025-10-13 06:54:30.631733 | controller | skipping: Conditional result was False 2025-10-13 06:54:30.650604 | 2025-10-13 06:54:30.650769 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-10-13 06:54:30.688664 | controller | skipping: Conditional result was False 2025-10-13 06:54:30.701421 | 2025-10-13 06:54:30.701568 | TASK [ensure-pip : Install Python 2 pip] 2025-10-13 06:54:30.737395 | controller | skipping: Conditional result was False 2025-10-13 06:54:30.745528 | 2025-10-13 06:54:30.745603 | TASK [ensure-pip : Ensure setuptools] 2025-10-13 06:54:30.760051 | controller | skipping: Conditional result was False 2025-10-13 06:54:30.767793 | 2025-10-13 06:54:30.767883 | TASK [ensure-pip : Check for ensurepip module] 2025-10-13 06:54:31.300683 | controller | skipping: Conditional result was False 2025-10-13 06:54:31.306658 | 2025-10-13 06:54:31.306731 | TASK [ensure-pip : Ensure python3-venv] 2025-10-13 06:54:31.324988 | controller | skipping: Conditional result was False 2025-10-13 06:54:31.333421 | 2025-10-13 06:54:31.333518 | TASK [ensure-pip : Install pip from source] 2025-10-13 06:54:31.360496 | controller | skipping: Conditional result was False 2025-10-13 06:54:31.366339 | 2025-10-13 06:54:31.366418 | TASK [ensure-pip : Probe for venv python full path] 2025-10-13 02:54:31.678677 | controller | /usr/bin/python3 2025-10-13 06:54:31.909761 | controller | ok: Runtime: 0:00:00.006312 2025-10-13 06:54:31.915634 | 2025-10-13 06:54:31.915697 | TASK [ensure-pip : Set host default] 2025-10-13 06:54:31.965165 | controller | ok 2025-10-13 06:54:31.970436 | 2025-10-13 06:54:31.970501 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-10-13 06:54:32.013666 | controller | ok 2025-10-13 06:54:32.024528 | 2025-10-13 06:54:32.024590 | TASK [bindep : Install bindep into temporary venv] 2025-10-13 06:54:36.540293 | controller | changed 2025-10-13 06:54:36.549393 | 2025-10-13 06:54:36.549529 | TASK [bindep : Define bindep_command] 2025-10-13 06:54:36.586752 | controller | ok 2025-10-13 06:54:36.595259 | 2025-10-13 06:54:36.595390 | LOOP [bindep : Include package tasks] 2025-10-13 06:54:36.645158 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-10-13 06:54:36.645388 | controller | ok: All items complete 2025-10-13 06:54:36.645426 | 2025-10-13 06:54:36.663372 | controller | included: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-10-13 06:54:36.683817 | 2025-10-13 06:54:36.683978 | TASK [bindep : Define bindep_run fact] 2025-10-13 06:54:36.726819 | controller | ok 2025-10-13 06:54:36.734129 | 2025-10-13 06:54:36.734228 | TASK [bindep : Get list of packages to install from bindep] 2025-10-13 02:54:38.207097 | controller | podman 2025-10-13 02:54:38.246394 | controller | python3-jmespath 2025-10-13 02:54:38.246552 | controller | python3-libvirt 2025-10-13 02:54:38.246561 | controller | python3-lxml 2025-10-13 02:54:38.246569 | controller | python3-netaddr 2025-10-13 06:54:38.283981 | controller | ok: Runtime: 0:00:01.238288 2025-10-13 06:54:38.290007 | 2025-10-13 06:54:38.290122 | TASK [bindep : Install distro packages from bindep] 2025-10-13 06:55:43.263910 | controller | changed 2025-10-13 06:55:43.269554 | 2025-10-13 06:55:43.269616 | TASK [bindep : Check that packages are installed] 2025-10-13 06:55:45.300707 | controller | ok: Runtime: 0:00:01.650555 2025-10-13 06:55:45.313618 | 2025-10-13 06:55:45.313819 | TASK [bindep : Fail if we cannot install all packages] 2025-10-13 06:55:45.340553 | controller | skipping: Conditional result was False 2025-10-13 06:55:45.363301 | 2025-10-13 06:55:45.363473 | TASK [Run test-setup role] 2025-10-13 06:55:45.386819 | controller | ok 2025-10-13 06:55:45.412386 | 2025-10-13 06:55:45.412515 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-13 06:55:45.639227 | controller | ok 2025-10-13 06:55:45.652417 | 2025-10-13 06:55:45.652676 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-13 06:55:46.202783 | controller | skipping: Conditional result was False 2025-10-13 06:55:46.246628 | 2025-10-13 06:55:46.246874 | TASK [bindep : Remove bindep temp dir] 2025-10-13 06:55:46.650621 | controller | ok 2025-10-13 06:55:46.661738 | 2025-10-13 06:55:46.661837 | PLAY RECAP 2025-10-13 06:55:46.661879 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-10-13 06:55:46.661900 | 2025-10-13 06:55:46.806453 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-13 06:55:46.807397 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-13 06:55:47.390534 | 2025-10-13 06:55:47.390644 | PLAY [all] 2025-10-13 06:55:47.434346 | 2025-10-13 06:55:47.434444 | TASK [Abort when test_command variable is undefined] 2025-10-13 06:55:47.484464 | controller | skipping: Conditional result was False 2025-10-13 06:55:47.490468 | 2025-10-13 06:55:47.490544 | TASK [Convert test_command to list] 2025-10-13 06:55:47.530698 | controller | skipping: Conditional result was False 2025-10-13 06:55:47.536829 | 2025-10-13 06:55:47.536907 | TASK [Use test_command list] 2025-10-13 06:55:47.586228 | controller | ok 2025-10-13 06:55:47.591719 | 2025-10-13 06:55:47.591783 | LOOP [Run test_command] 2025-10-13 06:55:47.986033 | controller | no check to run 2025-10-13 06:55:47.986223 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.007823 2025-10-13 06:55:48.017030 | 2025-10-13 06:55:48.017128 | PLAY RECAP 2025-10-13 06:55:48.017168 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-13 06:55:48.017189 | 2025-10-13 06:55:48.105111 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-13 06:55:48.105980 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-13 06:55:48.675522 | 2025-10-13 06:55:48.675629 | PLAY [all] 2025-10-13 06:55:48.695431 | 2025-10-13 06:55:48.695520 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-13 06:55:49.079819 | controller | changed: non-zero return code 2025-10-13 06:55:49.085157 | 2025-10-13 06:55:49.085227 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-13 06:55:49.098745 | controller | skipping: Conditional result was False 2025-10-13 06:55:49.104398 | 2025-10-13 06:55:49.104485 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-13 06:55:49.124567 | 2025-10-13 06:55:49.124723 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-13 06:55:49.144666 | 2025-10-13 06:55:49.144901 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-13 06:55:49.161401 | controller | skipping: Conditional result was False 2025-10-13 06:55:49.168205 | 2025-10-13 06:55:49.168300 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-13 06:55:49.190005 | 2025-10-13 06:55:49.190256 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-13 06:55:49.205790 | controller | skipping: Conditional result was False 2025-10-13 06:55:49.213296 | 2025-10-13 06:55:49.213390 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-13 06:55:49.230385 | controller | skipping: Conditional result was False 2025-10-13 06:55:49.238222 | 2025-10-13 06:55:49.238305 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-13 06:55:49.253661 | controller | skipping: Conditional result was False 2025-10-13 06:55:49.289332 | 2025-10-13 06:55:49.289414 | PLAY RECAP 2025-10-13 06:55:49.289455 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-13 06:55:49.289476 | 2025-10-13 06:55:49.380693 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-13 06:55:49.381875 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-13 06:55:50.317382 | 2025-10-13 06:55:50.317653 | PLAY [all] 2025-10-13 06:55:50.363352 | 2025-10-13 06:55:50.363498 | TASK [include_role : fetch-output] 2025-10-13 06:55:50.433527 | controller | ok 2025-10-13 06:55:50.460540 | 2025-10-13 06:55:50.460650 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-13 06:55:50.533338 | controller | skipping: Conditional result was False 2025-10-13 06:55:50.539108 | 2025-10-13 06:55:50.539176 | TASK [fetch-output : Set log path for single node] 2025-10-13 06:55:50.567714 | controller | ok 2025-10-13 06:55:50.574815 | 2025-10-13 06:55:50.574914 | LOOP [fetch-output : Ensure local output dirs] 2025-10-13 06:55:51.092861 | controller -> localhost | ok: "/var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/work/logs" 2025-10-13 06:55:51.446957 | controller -> localhost | changed: "/var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/work/artifacts" 2025-10-13 06:55:51.769248 | controller -> localhost | changed: "/var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/work/docs" 2025-10-13 06:55:51.781654 | 2025-10-13 06:55:51.781787 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-13 06:55:52.473346 | controller | changed: .d..t...... ./ 2025-10-13 06:55:52.473675 | controller | changed: All items complete 2025-10-13 06:55:52.473709 | 2025-10-13 06:55:52.995152 | controller | changed: .d..t...... ./ 2025-10-13 06:55:53.540672 | controller | changed: .d..t...... ./ 2025-10-13 06:55:53.556443 | 2025-10-13 06:55:53.556562 | TASK [include_role : fetch-output-openshift] 2025-10-13 06:55:53.601412 | controller | skipping: Conditional result was False 2025-10-13 06:55:53.607775 | 2025-10-13 06:55:53.607921 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-13 06:55:54.087067 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.018069 2025-10-13 06:55:54.343091 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.010692 2025-10-13 06:55:54.413962 | 2025-10-13 06:55:54.414108 | PLAY [all] 2025-10-13 06:55:54.435547 | 2025-10-13 06:55:54.435676 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-10-13 06:55:54.899975 | controller | changed 2025-10-13 06:55:54.955252 | 2025-10-13 06:55:54.955359 | PLAY RECAP 2025-10-13 06:55:54.955404 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-13 06:55:54.955425 | 2025-10-13 06:55:55.095339 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-13 06:55:55.096182 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-10-13 06:55:55.864225 | 2025-10-13 06:55:55.864319 | PLAY [localhost] 2025-10-13 06:55:55.899522 | 2025-10-13 06:55:55.899650 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-13 06:55:56.346168 | localhost | changed 2025-10-13 06:55:56.350938 | 2025-10-13 06:55:56.351016 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-13 06:55:56.379677 | localhost | ok 2025-10-13 06:55:56.389482 | 2025-10-13 06:55:56.389557 | TASK [add-fileserver : Create SSH private key tempfile] 2025-10-13 06:55:56.775880 | localhost | changed 2025-10-13 06:55:56.783526 | 2025-10-13 06:55:56.783625 | TASK [add-fileserver : Create SSH private key from secret] 2025-10-13 06:55:57.465449 | localhost | changed 2025-10-13 06:55:57.472175 | 2025-10-13 06:55:57.472277 | TASK [add-fileserver : Add fileserver ssh key] 2025-10-13 06:55:58.086240 | localhost | Identity added: /var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/work/tmp/ansible.f5cvye1t (/var/lib/zuul/builds/573f27c61c0144fcba702b04032aca6c/work/tmp/ansible.f5cvye1t) 2025-10-13 06:55:58.086445 | localhost | ok: Runtime: 0:00:00.012262 2025-10-13 06:55:58.090705 | 2025-10-13 06:55:58.090771 | TASK [add-fileserver : Remove SSH private key from disk] 2025-10-13 06:55:58.729904 | localhost | ok: Runtime: 0:00:00.032151 2025-10-13 06:55:58.746695 | 2025-10-13 06:55:58.746837 | TASK [add-fileserver : Add fileserver to inventory] 2025-10-13 06:55:58.813964 | localhost | changed 2025-10-13 06:55:58.819424 | 2025-10-13 06:55:58.819602 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-10-13 06:55:59.290867 | localhost | changed 2025-10-13 06:55:59.342513 | 2025-10-13 06:55:59.342628 | PLAY [localhost] 2025-10-13 06:55:59.362970 | 2025-10-13 06:55:59.363100 | TASK [Generate bulk log download script] 2025-10-13 06:55:59.410740 | localhost | ok 2025-10-13 06:55:59.434306 | 2025-10-13 06:55:59.434434 | TASK [local-log-download : Check API endpoint is defined] 2025-10-13 06:55:59.473280 | localhost | ok: All assertions passed 2025-10-13 06:55:59.479463 | 2025-10-13 06:55:59.479578 | TASK [local-log-download : Create download script] 2025-10-13 06:55:59.930884 | localhost -> localhost | changed 2025-10-13 06:55:59.941308 | 2025-10-13 06:55:59.941435 | TASK [Register quick-download link] 2025-10-13 06:56:00.025305 | localhost | ok 2025-10-13 06:56:00.059473 | 2025-10-13 06:56:00.059569 | PLAY [logserver.rdoproject.org] 2025-10-13 06:56:00.075652 | 2025-10-13 06:56:00.075717 | TASK [Set zuul-log-path fact] 2025-10-13 06:56:00.101844 | logserver.rdoproject.org | ok 2025-10-13 06:56:00.112924 | 2025-10-13 06:56:00.113004 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-13 06:56:00.159461 | logserver.rdoproject.org | ok 2025-10-13 06:56:00.164861 | 2025-10-13 06:56:00.164923 | TASK [upload-logs : Create log directories] 2025-10-13 06:56:00.756456 | logserver.rdoproject.org | changed 2025-10-13 06:56:00.759671 | 2025-10-13 06:56:00.759748 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-10-13 06:56:01.148283 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.009615 2025-10-13 06:56:01.153402 | 2025-10-13 06:56:01.153468 | TASK [upload-logs : Upload logs to log server] 2025-10-13 06:56:01.894860 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-10-13 06:56:01.902093 | 2025-10-13 06:56:01.902246 | LOOP [upload-logs : Compress console log and json output] 2025-10-13 06:56:01.966178 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 06:56:01.967154 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 06:56:01.973360 | 2025-10-13 06:56:01.973487 | LOOP [upload-logs : Upload compressed console log and json output] 2025-10-13 06:56:02.017889 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 06:56:02.018191 | 2025-10-13 06:56:02.020730 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 06:56:02.025114 | 2025-10-13 06:56:02.025237 | LOOP [upload-logs : Upload console log and json output]