2025-10-03 12:44:37.963331 | Job console starting... 2025-10-03 12:44:37.971787 | Updating repositories 2025-10-03 12:44:37.997237 | Preparing job workspace 2025-10-03 12:44:41.224889 | Running Ansible setup... 2025-10-03 12:44:44.827718 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-03 12:44:45.452114 | 2025-10-03 12:44:45.452239 | PLAY [localhost] 2025-10-03 12:44:45.461871 | 2025-10-03 12:44:45.461971 | TASK [Gathering Facts] 2025-10-03 12:44:46.386464 | localhost | ok 2025-10-03 12:44:46.400611 | 2025-10-03 12:44:46.400712 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-03 12:44:46.779612 | localhost -> localhost | changed 2025-10-03 12:44:46.784940 | 2025-10-03 12:44:46.785006 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-03 12:44:47.611161 | localhost -> localhost | changed 2025-10-03 12:44:47.629819 | 2025-10-03 12:44:47.629952 | TASK [Setup log path fact] 2025-10-03 12:44:47.655396 | localhost | ok 2025-10-03 12:44:47.680222 | 2025-10-03 12:44:47.680350 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-03 12:44:47.712419 | localhost | ok 2025-10-03 12:44:47.719867 | 2025-10-03 12:44:47.719931 | TASK [emit-job-header : Print job information] 2025-10-03 12:44:47.778635 | # Job Information 2025-10-03 12:44:47.778807 | Ansible Version: 2.15.12 2025-10-03 12:44:47.778837 | Job: cifmw-molecule-ovirt 2025-10-03 12:44:47.778857 | Pipeline: github-check 2025-10-03 12:44:47.778875 | Executor: ze04.softwarefactory-project.io 2025-10-03 12:44:47.778893 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3366 2025-10-03 12:44:47.778912 | Log URL (when completed): https://logserver.rdoproject.org/03e/rdoproject.org/03e3a89530304a2689d9cfeeda065a97/ 2025-10-03 12:44:47.778930 | Event ID: 8a294f00-a056-11f0-8eee-1e8238c96249 2025-10-03 12:44:47.782488 | 2025-10-03 12:44:47.782549 | LOOP [emit-job-header : Print node information] 2025-10-03 12:44:47.881124 | localhost | ok: 2025-10-03 12:44:47.881362 | localhost | # Node Information 2025-10-03 12:44:47.881392 | localhost | Inventory Hostname: controller 2025-10-03 12:44:47.881415 | localhost | Hostname: np0005468886 2025-10-03 12:44:47.881435 | localhost | Username: zuul 2025-10-03 12:44:47.881455 | localhost | Distro: CentOS 9 2025-10-03 12:44:47.881473 | localhost | Provider: vexxhost-nodepool-tripleo 2025-10-03 12:44:47.881490 | localhost | Region: RegionOne 2025-10-03 12:44:47.881506 | localhost | Label: cloud-centos-9-stream-tripleo 2025-10-03 12:44:47.881523 | localhost | Product Name: OpenStack Nova 2025-10-03 12:44:47.881540 | localhost | Interface IP: 38.102.83.181 2025-10-03 12:44:47.909878 | 2025-10-03 12:44:47.909940 | PLAY [all] 2025-10-03 12:44:47.916441 | 2025-10-03 12:44:47.916501 | TASK [Gather network facts] 2025-10-03 12:44:48.392811 | controller | ok 2025-10-03 12:44:48.422668 | 2025-10-03 12:44:48.422830 | TASK [include_role : start-zuul-console] 2025-10-03 12:44:48.445532 | controller | ok 2025-10-03 12:44:48.468937 | 2025-10-03 12:44:48.469066 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-03 12:44:48.879007 | controller | ok 2025-10-03 12:44:48.894256 | 2025-10-03 12:44:48.894365 | TASK [include_role : add-build-sshkey] 2025-10-03 12:44:48.927657 | controller | ok 2025-10-03 12:44:48.948784 | 2025-10-03 12:44:48.948853 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-03 12:44:49.165035 | controller -> localhost | ok 2025-10-03 12:44:49.174386 | 2025-10-03 12:44:49.174455 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-03 12:44:49.202819 | controller | ok 2025-10-03 12:44:49.226244 | controller | included: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-03 12:44:49.232121 | 2025-10-03 12:44:49.232183 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-03 12:44:49.886164 | controller -> localhost | Generating public/private rsa key pair. 2025-10-03 12:44:49.886391 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/work/03e3a89530304a2689d9cfeeda065a97_id_rsa. 2025-10-03 12:44:49.886423 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/work/03e3a89530304a2689d9cfeeda065a97_id_rsa.pub. 2025-10-03 12:44:49.886446 | controller -> localhost | The key fingerprint is: 2025-10-03 12:44:49.886466 | controller -> localhost | SHA256:LaW29ZD+gpCVhjvtAFQSTi8af5afdUozzPR+lLI73rg zuul-build-sshkey 2025-10-03 12:44:49.886485 | controller -> localhost | The key's randomart image is: 2025-10-03 12:44:49.886504 | controller -> localhost | +---[RSA 3072]----+ 2025-10-03 12:44:49.886523 | controller -> localhost | | +o. | 2025-10-03 12:44:49.886541 | controller -> localhost | | o.o | 2025-10-03 12:44:49.886560 | controller -> localhost | | ..o .. .o | 2025-10-03 12:44:49.886578 | controller -> localhost | | +....+B o . | 2025-10-03 12:44:49.886596 | controller -> localhost | | . ..+*S % + o | 2025-10-03 12:44:49.886614 | controller -> localhost | | o*o.O O + | 2025-10-03 12:44:49.886631 | controller -> localhost | | =+.o + . | 2025-10-03 12:44:49.886651 | controller -> localhost | | o ...= | 2025-10-03 12:44:49.886669 | controller -> localhost | | oEo. | 2025-10-03 12:44:49.886708 | controller -> localhost | +----[SHA256]-----+ 2025-10-03 12:44:49.886752 | controller -> localhost | ok: Runtime: 0:00:00.262920 2025-10-03 12:44:49.893240 | 2025-10-03 12:44:49.893299 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-03 12:44:49.922268 | controller | ok 2025-10-03 12:44:49.932700 | controller | included: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-03 12:44:49.941228 | 2025-10-03 12:44:49.941289 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-03 12:44:49.965169 | controller | skipping: Conditional result was False 2025-10-03 12:44:49.971210 | 2025-10-03 12:44:49.971276 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-03 12:44:50.469874 | controller | changed 2025-10-03 12:44:50.476214 | 2025-10-03 12:44:50.476272 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-03 12:44:50.770196 | controller | ok 2025-10-03 12:44:50.775317 | 2025-10-03 12:44:50.775377 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-03 12:44:51.604757 | controller | changed 2025-10-03 12:44:51.609671 | 2025-10-03 12:44:51.609745 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-03 12:44:52.503977 | controller | changed 2025-10-03 12:44:52.509471 | 2025-10-03 12:44:52.509533 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-03 12:44:52.534246 | controller | skipping: Conditional result was False 2025-10-03 12:44:52.541075 | 2025-10-03 12:44:52.541156 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-03 12:44:52.961814 | controller -> localhost | changed 2025-10-03 12:44:52.972256 | 2025-10-03 12:44:52.972331 | TASK [add-build-sshkey : Add back temp key] 2025-10-03 12:44:53.240736 | controller -> localhost | Identity added: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/work/03e3a89530304a2689d9cfeeda065a97_id_rsa (zuul-build-sshkey) 2025-10-03 12:44:53.240908 | controller -> localhost | ok: Runtime: 0:00:00.012643 2025-10-03 12:44:53.246409 | 2025-10-03 12:44:53.246468 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-03 12:44:53.621992 | controller | ok 2025-10-03 12:44:53.628883 | 2025-10-03 12:44:53.628964 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-03 12:44:53.655558 | controller | skipping: Conditional result was False 2025-10-03 12:44:53.678043 | 2025-10-03 12:44:53.678173 | TASK [include_role : validate-host] 2025-10-03 12:44:53.698447 | controller | ok 2025-10-03 12:44:53.721499 | 2025-10-03 12:44:53.721589 | TASK [validate-host : Define zuul_info_dir fact] 2025-10-03 12:44:53.749228 | controller | ok 2025-10-03 12:44:53.753845 | 2025-10-03 12:44:53.753903 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-10-03 12:44:53.979952 | controller -> localhost | ok 2025-10-03 12:44:53.985530 | 2025-10-03 12:44:53.985590 | TASK [validate-host : Collect information about the host] 2025-10-03 12:44:54.807255 | controller | ok 2025-10-03 12:44:54.815473 | 2025-10-03 12:44:54.815557 | TASK [validate-host : Sanitize hostname] 2025-10-03 12:44:54.864293 | controller | ok 2025-10-03 12:44:54.876430 | 2025-10-03 12:44:54.876524 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-10-03 12:44:55.319842 | controller -> localhost | changed 2025-10-03 12:44:55.325607 | 2025-10-03 12:44:55.325669 | TASK [validate-host : Collect information about zuul worker] 2025-10-03 12:44:55.715990 | controller | ok 2025-10-03 12:44:55.723040 | 2025-10-03 12:44:55.723125 | TASK [validate-host : Write out all zuul information for each host] 2025-10-03 12:44:56.154128 | controller -> localhost | changed 2025-10-03 12:44:56.165597 | 2025-10-03 12:44:56.165662 | TASK [include_role : prepare-workspace-openshift] 2025-10-03 12:44:56.199530 | controller | skipping: Conditional result was False 2025-10-03 12:44:56.215132 | 2025-10-03 12:44:56.215217 | TASK [include_role : remove-zuul-sshkey] 2025-10-03 12:44:56.242914 | controller | skipping: Conditional result was False 2025-10-03 12:44:56.248823 | 2025-10-03 12:44:56.248903 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-03 12:44:56.489640 | controller | ok: "logs" 2025-10-03 12:44:56.489910 | controller | ok: All items complete 2025-10-03 12:44:56.489938 | 2025-10-03 12:44:56.674661 | controller | ok: "artifacts" 2025-10-03 12:44:56.892594 | controller | ok: "docs" 2025-10-03 12:44:56.905206 | 2025-10-03 12:44:56.905346 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-03 12:44:57.234108 | controller | changed: "logs" 2025-10-03 12:44:57.459543 | controller | changed: "artifacts" 2025-10-03 12:44:57.706173 | controller | changed: "docs" 2025-10-03 12:44:57.738536 | 2025-10-03 12:44:57.738805 | PLAY RECAP 2025-10-03 12:44:57.738853 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-03 12:44:57.738878 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-03 12:44:57.738896 | 2025-10-03 12:44:57.911195 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-03 12:44:57.912013 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-03 12:44:58.764241 | 2025-10-03 12:44:58.764348 | PLAY [localhost] 2025-10-03 12:44:58.781102 | 2025-10-03 12:44:58.781177 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-10-03 12:44:59.197477 | localhost | ok 2025-10-03 12:44:59.207897 | 2025-10-03 12:44:59.207998 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-10-03 12:44:59.826029 | localhost | changed 2025-10-03 12:44:59.862528 | 2025-10-03 12:44:59.862616 | PLAY [all] 2025-10-03 12:44:59.878636 | 2025-10-03 12:44:59.878714 | TASK [include_role : prepare-workspace] 2025-10-03 12:44:59.918537 | controller | ok 2025-10-03 12:44:59.934247 | 2025-10-03 12:44:59.934324 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-03 12:45:00.344780 | controller | ok 2025-10-03 12:45:00.352651 | 2025-10-03 12:45:00.352742 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-03 12:45:02.139823 | controller | Output suppressed because no_log was given 2025-10-03 12:45:02.155307 | 2025-10-03 12:45:02.155405 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-03 12:45:02.417068 | controller | changed: "logs" 2025-10-03 12:45:02.645066 | controller | changed: "artifacts" 2025-10-03 12:45:02.889958 | controller | changed: "docs" 2025-10-03 12:45:02.904415 | 2025-10-03 12:45:02.904532 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-03 12:45:03.195352 | controller | changed: "logs" 2025-10-03 12:45:03.195932 | controller | changed: All items complete 2025-10-03 12:45:03.195999 | 2025-10-03 12:45:03.447017 | controller | changed: "artifacts" 2025-10-03 12:45:03.681561 | controller | changed: "docs" 2025-10-03 12:45:03.703477 | 2025-10-03 12:45:03.703568 | TASK [Check if worker can sudo] 2025-10-03 12:45:04.235863 | controller | ok: Runtime: 0:00:00.049512 2025-10-03 12:45:04.248911 | 2025-10-03 12:45:04.249057 | TASK [configure-mirrors : Gather needed facts] 2025-10-03 12:45:04.325433 | controller | skipping: Conditional result was False 2025-10-03 12:45:04.333805 | 2025-10-03 12:45:04.333898 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-10-03 12:45:04.394579 | controller | ok 2025-10-03 12:45:04.401933 | controller | included: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-10-03 12:45:04.407557 | 2025-10-03 12:45:04.407617 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-10-03 12:45:04.764357 | controller | ok 2025-10-03 12:45:04.772079 | 2025-10-03 12:45:04.772160 | LOOP [configure-mirrors : Include OS-specific variables] 2025-10-03 12:45:04.831529 | controller | ok: "/var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-10-03 12:45:04.852059 | 2025-10-03 12:45:04.852205 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-10-03 12:45:05.757621 | controller | changed 2025-10-03 12:45:05.764971 | 2025-10-03 12:45:05.765077 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-10-03 12:45:05.844982 | controller | ok: "/var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-10-03 12:45:05.845174 | controller | ok: All items complete 2025-10-03 12:45:05.845209 | 2025-10-03 12:45:05.895668 | controller | included: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-10-03 12:45:05.902950 | 2025-10-03 12:45:05.903035 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-10-03 12:45:06.820047 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-10-03 12:45:07.622783 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-10-03 12:45:07.639489 | 2025-10-03 12:45:07.639631 | TASK [configure-mirrors : Disable deltrarpm] 2025-10-03 12:45:08.091847 | controller | changed: section and option added 2025-10-03 12:45:08.115596 | 2025-10-03 12:45:08.115737 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-10-03 12:45:08.939365 | controller | 29 files removed 2025-10-03 12:45:08.939585 | controller | ok: Item: dnf clean all Runtime: 0:00:00.518893 2025-10-03 12:45:08.939627 | controller | changed: All items complete 2025-10-03 12:45:08.939648 | 2025-10-03 12:45:20.013005 | 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-03 12:45:20.013155 | controller | DNF version: 4.14.0 2025-10-03 12:45:20.013182 | controller | cachedir: /var/cache/dnf 2025-10-03 12:45:20.013202 | controller | Making cache files for all metadata files. 2025-10-03 12:45:20.013220 | controller | baseos: has expired and will be refreshed. 2025-10-03 12:45:20.013237 | controller | appstream: has expired and will be refreshed. 2025-10-03 12:45:20.013254 | controller | crb: has expired and will be refreshed. 2025-10-03 12:45:20.013277 | controller | extras-common: has expired and will be refreshed. 2025-10-03 12:45:20.013295 | controller | repo: downloading from remote: baseos 2025-10-03 12:45:20.013311 | controller | CentOS Stream 9 - BaseOS 73 MB/s | 8.8 MB 00:00 2025-10-03 12:45:20.013327 | controller | baseos: using metadata from Tue 30 Sep 2025 01:12:56 PM EDT. 2025-10-03 12:45:20.013343 | controller | repo: downloading from remote: appstream 2025-10-03 12:45:20.013359 | controller | CentOS Stream 9 - AppStream 98 MB/s | 25 MB 00:00 2025-10-03 12:45:20.013375 | controller | appstream: using metadata from Tue 30 Sep 2025 01:16:29 PM EDT. 2025-10-03 12:45:20.013390 | controller | repo: downloading from remote: crb 2025-10-03 12:45:20.013406 | controller | CentOS Stream 9 - CRB 64 MB/s | 7.1 MB 00:00 2025-10-03 12:45:20.013422 | controller | crb: using metadata from Tue 30 Sep 2025 01:20:54 PM EDT. 2025-10-03 12:45:20.013438 | controller | repo: downloading from remote: extras-common 2025-10-03 12:45:20.013454 | controller | CentOS Stream 9 - Extras packages 1.7 MB/s | 20 kB 00:00 2025-10-03 12:45:20.013470 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-10-03 12:45:20.013485 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-10-03 12:45:20.013501 | controller | Completion plugin: Generating completion cache... 2025-10-03 12:45:20.013517 | controller | Metadata cache created. 2025-10-03 12:45:20.013541 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.824110 2025-10-03 12:45:20.026757 | 2025-10-03 12:45:20.026848 | PLAY RECAP 2025-10-03 12:45:20.027149 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-03 12:45:20.027185 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-03 12:45:20.027204 | 2025-10-03 12:45:20.168517 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-03 12:45:20.169341 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-03 12:45:20.782264 | 2025-10-03 12:45:20.782390 | PLAY [all] 2025-10-03 12:45:20.806455 | 2025-10-03 12:45:20.806570 | TASK [Install binary dependencies] 2025-10-03 12:45:20.856662 | controller | ok 2025-10-03 12:45:20.881061 | 2025-10-03 12:45:20.881159 | TASK [bindep : Include find tasks] 2025-10-03 12:45:20.910013 | controller | ok 2025-10-03 12:45:20.919049 | controller | included: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-03 12:45:20.926360 | 2025-10-03 12:45:20.926425 | TASK [bindep : Look for bindep.txt] 2025-10-03 12:45:21.356391 | controller | ok 2025-10-03 12:45:21.365362 | 2025-10-03 12:45:21.365492 | TASK [bindep : Define bindep_file fact] 2025-10-03 12:45:21.395282 | controller | ok 2025-10-03 12:45:21.400713 | 2025-10-03 12:45:21.400778 | TASK [bindep : Look for other-requirements.txt] 2025-10-03 12:45:21.433548 | controller | skipping: Conditional result was False 2025-10-03 12:45:21.439710 | 2025-10-03 12:45:21.439782 | TASK [bindep : Define bindep_file fact] 2025-10-03 12:45:21.463530 | controller | skipping: Conditional result was False 2025-10-03 12:45:21.469603 | 2025-10-03 12:45:21.469674 | TASK [bindep : Look for bindep fallback file] 2025-10-03 12:45:21.493509 | controller | skipping: Conditional result was False 2025-10-03 12:45:21.499264 | 2025-10-03 12:45:21.499333 | TASK [bindep : Define bindep_file fact] 2025-10-03 12:45:21.522670 | controller | skipping: Conditional result was False 2025-10-03 12:45:21.529411 | 2025-10-03 12:45:21.529477 | TASK [bindep : Include bindep tasks] 2025-10-03 12:45:21.559181 | controller | ok 2025-10-03 12:45:21.566021 | controller | included: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-10-03 12:45:21.573737 | 2025-10-03 12:45:21.573797 | TASK [bindep : Look for bindep command] 2025-10-03 12:45:21.596851 | controller | skipping: Conditional result was False 2025-10-03 12:45:21.603567 | 2025-10-03 12:45:21.603630 | TASK [bindep : Check for system bindep] 2025-10-03 12:45:22.133822 | controller | ok: Runtime: 0:00:00.006046 2025-10-03 12:45:22.139524 | 2025-10-03 12:45:22.139590 | TASK [bindep : Define bindep_command fact] 2025-10-03 12:45:22.173569 | controller | skipping: Conditional result was False 2025-10-03 12:45:22.179388 | 2025-10-03 12:45:22.179460 | TASK [bindep : Include install tasks] 2025-10-03 12:45:22.207397 | controller | ok 2025-10-03 12:45:22.215548 | controller | included: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-10-03 12:45:22.225189 | 2025-10-03 12:45:22.225312 | TASK [bindep : Create temp dir for bindep] 2025-10-03 12:45:22.600430 | controller | changed 2025-10-03 12:45:22.614152 | 2025-10-03 12:45:22.614293 | TASK [Ensure we have pip dependencies] 2025-10-03 12:45:22.643492 | controller | ok 2025-10-03 12:45:22.706778 | 2025-10-03 12:45:22.706892 | TASK [ensure-pip : Check if pip is installed] 2025-10-03 08:45:22.982382 | controller | /usr/bin/pip3 2025-10-03 08:45:23.002562 | controller | /usr/bin/python3: No module named wheel 2025-10-03 12:45:23.238748 | controller | ok: Runtime: 0:00:00.030835 2025-10-03 12:45:23.244661 | 2025-10-03 12:45:23.244746 | LOOP [ensure-pip : Install pip from packages] 2025-10-03 12:45:23.275613 | controller | ok: "/var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-10-03 12:45:23.287192 | controller | included: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-10-03 12:45:23.299424 | 2025-10-03 12:45:23.299528 | TASK [ensure-pip : Install Python 3 pip] 2025-10-03 12:45:25.751388 | controller | changed 2025-10-03 12:45:25.756707 | 2025-10-03 12:45:25.756768 | TASK [ensure-pip : Check for EPEL repository] 2025-10-03 12:45:25.831738 | controller | skipping: Conditional result was False 2025-10-03 12:45:25.837892 | 2025-10-03 12:45:25.837958 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-10-03 12:45:25.872598 | controller | skipping: Conditional result was False 2025-10-03 12:45:25.881171 | 2025-10-03 12:45:25.881247 | TASK [ensure-pip : Install Python 2 pip] 2025-10-03 12:45:25.920560 | controller | skipping: Conditional result was False 2025-10-03 12:45:25.927863 | 2025-10-03 12:45:25.927946 | TASK [ensure-pip : Ensure setuptools] 2025-10-03 12:45:25.946120 | controller | skipping: Conditional result was False 2025-10-03 12:45:25.952416 | 2025-10-03 12:45:25.952480 | TASK [ensure-pip : Check for ensurepip module] 2025-10-03 12:45:26.485723 | controller | skipping: Conditional result was False 2025-10-03 12:45:26.492518 | 2025-10-03 12:45:26.492619 | TASK [ensure-pip : Ensure python3-venv] 2025-10-03 12:45:26.517042 | controller | skipping: Conditional result was False 2025-10-03 12:45:26.523982 | 2025-10-03 12:45:26.524069 | TASK [ensure-pip : Install pip from source] 2025-10-03 12:45:26.548758 | controller | skipping: Conditional result was False 2025-10-03 12:45:26.555079 | 2025-10-03 12:45:26.555146 | TASK [ensure-pip : Probe for venv python full path] 2025-10-03 08:45:26.836780 | controller | /usr/bin/python3 2025-10-03 12:45:27.088458 | controller | ok: Runtime: 0:00:00.007224 2025-10-03 12:45:27.093918 | 2025-10-03 12:45:27.093981 | TASK [ensure-pip : Set host default] 2025-10-03 12:45:27.154947 | controller | ok 2025-10-03 12:45:27.160230 | 2025-10-03 12:45:27.160294 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-10-03 12:45:27.220438 | controller | ok 2025-10-03 12:45:27.230813 | 2025-10-03 12:45:27.230878 | TASK [bindep : Install bindep into temporary venv] 2025-10-03 12:45:31.682568 | controller | changed 2025-10-03 12:45:31.688157 | 2025-10-03 12:45:31.688221 | TASK [bindep : Define bindep_command] 2025-10-03 12:45:31.746396 | controller | ok 2025-10-03 12:45:31.753653 | 2025-10-03 12:45:31.753772 | LOOP [bindep : Include package tasks] 2025-10-03 12:45:31.816749 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-10-03 12:45:31.816922 | controller | ok: All items complete 2025-10-03 12:45:31.816950 | 2025-10-03 12:45:31.836902 | controller | included: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-10-03 12:45:31.861165 | 2025-10-03 12:45:31.861257 | TASK [bindep : Define bindep_run fact] 2025-10-03 12:45:31.892903 | controller | ok 2025-10-03 12:45:31.899980 | 2025-10-03 12:45:31.900068 | TASK [bindep : Get list of packages to install from bindep] 2025-10-03 08:45:33.286220 | controller | podman 2025-10-03 08:45:33.314439 | controller | python3-jmespath 2025-10-03 08:45:33.314513 | controller | python3-libvirt 2025-10-03 08:45:33.314521 | controller | python3-lxml 2025-10-03 08:45:33.314529 | controller | python3-netaddr 2025-10-03 12:45:33.437026 | controller | ok: Runtime: 0:00:01.148109 2025-10-03 12:45:33.452099 | 2025-10-03 12:45:33.452260 | TASK [bindep : Install distro packages from bindep] 2025-10-03 12:46:39.847074 | controller | changed 2025-10-03 12:46:39.860955 | 2025-10-03 12:46:39.861135 | TASK [bindep : Check that packages are installed] 2025-10-03 12:46:41.439916 | controller | ok: Runtime: 0:00:01.113860 2025-10-03 12:46:41.448918 | 2025-10-03 12:46:41.449020 | TASK [bindep : Fail if we cannot install all packages] 2025-10-03 12:46:41.474300 | controller | skipping: Conditional result was False 2025-10-03 12:46:41.490408 | 2025-10-03 12:46:41.490547 | TASK [Run test-setup role] 2025-10-03 12:46:41.513446 | controller | ok 2025-10-03 12:46:41.537968 | 2025-10-03 12:46:41.538061 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-03 12:46:41.759853 | controller | ok 2025-10-03 12:46:41.764926 | 2025-10-03 12:46:41.764987 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-03 12:46:42.296953 | controller | skipping: Conditional result was False 2025-10-03 12:46:42.342340 | 2025-10-03 12:46:42.342983 | TASK [bindep : Remove bindep temp dir] 2025-10-03 12:46:42.674307 | controller | ok 2025-10-03 12:46:42.685602 | 2025-10-03 12:46:42.685716 | PLAY RECAP 2025-10-03 12:46:42.685761 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-10-03 12:46:42.685782 | 2025-10-03 12:46:42.786363 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-03 12:46:42.787200 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-03 12:46:43.321782 | 2025-10-03 12:46:43.321886 | PLAY [all] 2025-10-03 12:46:43.342328 | 2025-10-03 12:46:43.342426 | TASK [Abort when test_command variable is undefined] 2025-10-03 12:46:43.366864 | controller | skipping: Conditional result was False 2025-10-03 12:46:43.372353 | 2025-10-03 12:46:43.372425 | TASK [Convert test_command to list] 2025-10-03 12:46:43.416490 | controller | skipping: Conditional result was False 2025-10-03 12:46:43.423127 | 2025-10-03 12:46:43.423194 | TASK [Use test_command list] 2025-10-03 12:46:43.482317 | controller | ok 2025-10-03 12:46:43.488376 | 2025-10-03 12:46:43.488437 | LOOP [Run test_command] 2025-10-03 12:46:43.879227 | controller | no check to run 2025-10-03 12:46:43.879393 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.006740 2025-10-03 12:46:43.945239 | 2025-10-03 12:46:43.945376 | PLAY RECAP 2025-10-03 12:46:43.945434 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-03 12:46:43.945461 | 2025-10-03 12:46:44.036043 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-03 12:46:44.036889 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-03 12:46:44.606459 | 2025-10-03 12:46:44.606554 | PLAY [all] 2025-10-03 12:46:44.627101 | 2025-10-03 12:46:44.627188 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-03 12:46:44.989138 | controller | changed: non-zero return code 2025-10-03 12:46:45.001855 | 2025-10-03 12:46:45.002030 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-03 12:46:45.029138 | controller | skipping: Conditional result was False 2025-10-03 12:46:45.037853 | 2025-10-03 12:46:45.037968 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-03 12:46:45.078858 | 2025-10-03 12:46:45.079145 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-03 12:46:45.118789 | 2025-10-03 12:46:45.119051 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-03 12:46:45.135924 | controller | skipping: Conditional result was False 2025-10-03 12:46:45.151219 | 2025-10-03 12:46:45.151409 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-03 12:46:45.184708 | 2025-10-03 12:46:45.184884 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-03 12:46:45.199712 | controller | skipping: Conditional result was False 2025-10-03 12:46:45.209923 | 2025-10-03 12:46:45.210016 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-03 12:46:45.224323 | controller | skipping: Conditional result was False 2025-10-03 12:46:45.232576 | 2025-10-03 12:46:45.232664 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-03 12:46:45.247212 | controller | skipping: Conditional result was False 2025-10-03 12:46:45.279226 | 2025-10-03 12:46:45.279286 | PLAY RECAP 2025-10-03 12:46:45.279329 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-03 12:46:45.279348 | 2025-10-03 12:46:45.369467 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-03 12:46:45.370249 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-03 12:46:45.981476 | 2025-10-03 12:46:45.981591 | PLAY [all] 2025-10-03 12:46:46.001213 | 2025-10-03 12:46:46.001332 | TASK [include_role : fetch-output] 2025-10-03 12:46:46.030537 | controller | ok 2025-10-03 12:46:46.049751 | 2025-10-03 12:46:46.049886 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-03 12:46:46.106035 | controller | skipping: Conditional result was False 2025-10-03 12:46:46.111810 | 2025-10-03 12:46:46.111880 | TASK [fetch-output : Set log path for single node] 2025-10-03 12:46:46.141621 | controller | ok 2025-10-03 12:46:46.147414 | 2025-10-03 12:46:46.147484 | LOOP [fetch-output : Ensure local output dirs] 2025-10-03 12:46:46.531079 | controller -> localhost | ok: "/var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/work/logs" 2025-10-03 12:46:46.786351 | controller -> localhost | changed: "/var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/work/artifacts" 2025-10-03 12:46:46.984048 | controller -> localhost | changed: "/var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/work/docs" 2025-10-03 12:46:46.993990 | 2025-10-03 12:46:46.994108 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-03 12:46:47.641938 | controller | changed: .d..t...... ./ 2025-10-03 12:46:47.642125 | controller | changed: All items complete 2025-10-03 12:46:47.642152 | 2025-10-03 12:46:48.078867 | controller | changed: .d..t...... ./ 2025-10-03 12:46:48.563364 | controller | changed: .d..t...... ./ 2025-10-03 12:46:48.581353 | 2025-10-03 12:46:48.581469 | TASK [include_role : fetch-output-openshift] 2025-10-03 12:46:48.595770 | controller | skipping: Conditional result was False 2025-10-03 12:46:48.603327 | 2025-10-03 12:46:48.603419 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-03 12:46:49.001552 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.014353 2025-10-03 12:46:49.217362 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.009079 2025-10-03 12:46:49.246377 | 2025-10-03 12:46:49.246476 | PLAY [all] 2025-10-03 12:46:49.262105 | 2025-10-03 12:46:49.262201 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-10-03 12:46:49.713348 | controller | changed 2025-10-03 12:46:49.745870 | 2025-10-03 12:46:49.745958 | PLAY RECAP 2025-10-03 12:46:49.745999 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-03 12:46:49.746020 | 2025-10-03 12:46:49.855696 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-03 12:46:49.856464 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-10-03 12:46:50.503654 | 2025-10-03 12:46:50.503831 | PLAY [localhost] 2025-10-03 12:46:50.524392 | 2025-10-03 12:46:50.524508 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-03 12:46:50.899193 | localhost | changed 2025-10-03 12:46:50.904753 | 2025-10-03 12:46:50.904845 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-03 12:46:50.934602 | localhost | ok 2025-10-03 12:46:50.943608 | 2025-10-03 12:46:50.943754 | TASK [add-fileserver : Create SSH private key tempfile] 2025-10-03 12:46:51.300367 | localhost | changed 2025-10-03 12:46:51.309168 | 2025-10-03 12:46:51.309277 | TASK [add-fileserver : Create SSH private key from secret] 2025-10-03 12:46:51.969741 | localhost | changed 2025-10-03 12:46:51.978810 | 2025-10-03 12:46:51.978890 | TASK [add-fileserver : Add fileserver ssh key] 2025-10-03 12:46:52.394313 | localhost | Identity added: /var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/work/tmp/ansible.c1i8r5yb (/var/lib/zuul/builds/03e3a89530304a2689d9cfeeda065a97/work/tmp/ansible.c1i8r5yb) 2025-10-03 12:46:52.394522 | localhost | ok: Runtime: 0:00:00.019814 2025-10-03 12:46:52.399052 | 2025-10-03 12:46:52.399122 | TASK [add-fileserver : Remove SSH private key from disk] 2025-10-03 12:46:52.647660 | localhost | ok: Runtime: 0:00:00.007662 2025-10-03 12:46:52.655576 | 2025-10-03 12:46:52.655647 | TASK [add-fileserver : Add fileserver to inventory] 2025-10-03 12:46:52.704257 | localhost | changed 2025-10-03 12:46:52.709413 | 2025-10-03 12:46:52.709482 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-10-03 12:46:53.094317 | localhost | changed 2025-10-03 12:46:53.118026 | 2025-10-03 12:46:53.118146 | PLAY [localhost] 2025-10-03 12:46:53.130765 | 2025-10-03 12:46:53.130870 | TASK [Generate bulk log download script] 2025-10-03 12:46:53.170046 | localhost | ok 2025-10-03 12:46:53.184547 | 2025-10-03 12:46:53.184659 | TASK [local-log-download : Check API endpoint is defined] 2025-10-03 12:46:53.213061 | localhost | ok: All assertions passed 2025-10-03 12:46:53.217751 | 2025-10-03 12:46:53.217818 | TASK [local-log-download : Create download script] 2025-10-03 12:46:53.629508 | localhost -> localhost | changed 2025-10-03 12:46:53.638953 | 2025-10-03 12:46:53.639021 | TASK [Register quick-download link] 2025-10-03 12:46:53.656751 | localhost | ok 2025-10-03 12:46:53.701512 | 2025-10-03 12:46:53.701619 | PLAY [logserver.rdoproject.org] 2025-10-03 12:46:53.713227 | 2025-10-03 12:46:53.713301 | TASK [Set zuul-log-path fact] 2025-10-03 12:46:53.730207 | logserver.rdoproject.org | ok 2025-10-03 12:46:53.741253 | 2025-10-03 12:46:53.741366 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-03 12:46:53.768405 | logserver.rdoproject.org | ok 2025-10-03 12:46:53.774051 | 2025-10-03 12:46:53.774118 | TASK [upload-logs : Create log directories] 2025-10-03 12:46:54.529462 | logserver.rdoproject.org | changed 2025-10-03 12:46:54.533443 | 2025-10-03 12:46:54.533533 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-10-03 12:46:54.841979 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.006218 2025-10-03 12:46:54.847380 | 2025-10-03 12:46:54.847463 | TASK [upload-logs : Upload logs to log server] 2025-10-03 12:46:55.492486 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-10-03 12:46:55.498849 | 2025-10-03 12:46:55.498990 | LOOP [upload-logs : Compress console log and json output] 2025-10-03 12:46:55.561486 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-03 12:46:55.570662 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-03 12:46:55.584715 | 2025-10-03 12:46:55.584912 | LOOP [upload-logs : Upload compressed console log and json output] 2025-10-03 12:46:55.626239 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-03 12:46:55.626664 | 2025-10-03 12:46:55.629552 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-03 12:46:55.642188 | 2025-10-03 12:46:55.642363 | LOOP [upload-logs : Upload console log and json output]