2025-09-30 06:39:50.232592 | Job console starting...
2025-09-30 06:39:50.244341 | Updating repositories
2025-09-30 06:39:50.289149 | Preparing job workspace
2025-09-30 06:39:54.964798 | Running Ansible setup...
2025-09-30 06:39:59.087489 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 06:39:59.729918 | 
2025-09-30 06:39:59.730046 | PLAY [localhost]
2025-09-30 06:39:59.739100 | 
2025-09-30 06:39:59.739206 | TASK [Gathering Facts]
2025-09-30 06:40:00.819088 | localhost | ok
2025-09-30 06:40:00.860433 | 
2025-09-30 06:40:00.863828 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-30 06:40:01.494250 | localhost -> localhost | changed
2025-09-30 06:40:01.501042 | 
2025-09-30 06:40:01.501114 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-30 06:40:02.571255 | localhost -> localhost | changed
2025-09-30 06:40:02.579595 | 
2025-09-30 06:40:02.579663 | TASK [Setup log path fact]
2025-09-30 06:40:02.599048 | localhost | ok
2025-09-30 06:40:02.610763 | 
2025-09-30 06:40:02.610847 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 06:40:02.638688 | localhost | ok
2025-09-30 06:40:02.646358 | 
2025-09-30 06:40:02.646429 | TASK [emit-job-header : Print job information]
2025-09-30 06:40:02.675295 | # Job Information
2025-09-30 06:40:02.675433 | Ansible Version: 2.15.12
2025-09-30 06:40:02.675458 | Job: cifmw-molecule-ipa
2025-09-30 06:40:02.675477 | Pipeline: github-check
2025-09-30 06:40:02.675494 | Executor: ze01.softwarefactory-project.io
2025-09-30 06:40:02.675511 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333
2025-09-30 06:40:02.675530 | Log URL (when completed): https://logserver.rdoproject.org/7f0/rdoproject.org/7f0c0fe7e569418082852224b2f04c37/
2025-09-30 06:40:02.675548 | Event ID: 04e0d970-9dc8-11f0-9216-1f816847bc0d
2025-09-30 06:40:02.679101 | 
2025-09-30 06:40:02.679167 | LOOP [emit-job-header : Print node information]
2025-09-30 06:40:02.804952 | localhost | ok:
2025-09-30 06:40:02.805164 | localhost | # Node Information
2025-09-30 06:40:02.805194 | localhost | Inventory Hostname: controller
2025-09-30 06:40:02.805220 | localhost | Hostname: np0005461806
2025-09-30 06:40:02.805241 | localhost | Username: zuul
2025-09-30 06:40:02.805260 | localhost | Distro: CentOS 9
2025-09-30 06:40:02.805277 | localhost | Provider: vexxhost-nodepool-tripleo
2025-09-30 06:40:02.805294 | localhost | Region: RegionOne
2025-09-30 06:40:02.805310 | localhost | Label: cloud-centos-9-stream-tripleo
2025-09-30 06:40:02.805326 | localhost | Product Name: OpenStack Nova
2025-09-30 06:40:02.805341 | localhost | Interface IP: 38.102.83.175
2025-09-30 06:40:02.833317 | 
2025-09-30 06:40:02.833423 | PLAY [all]
2025-09-30 06:40:02.848431 | 
2025-09-30 06:40:02.848563 | TASK [Gather network facts]
2025-09-30 06:40:03.396067 | controller | ok
2025-09-30 06:40:03.420364 | 
2025-09-30 06:40:03.420469 | TASK [include_role : start-zuul-console]
2025-09-30 06:40:03.460201 | controller | ok
2025-09-30 06:40:03.482537 | 
2025-09-30 06:40:03.482633 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-30 06:40:04.012487 | controller | ok
2025-09-30 06:40:04.029538 | 
2025-09-30 06:40:04.029634 | TASK [include_role : add-build-sshkey]
2025-09-30 06:40:04.072448 | controller | ok
2025-09-30 06:40:04.095193 | 
2025-09-30 06:40:04.095308 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-30 06:40:04.422924 | controller -> localhost | ok
2025-09-30 06:40:04.428560 | 
2025-09-30 06:40:04.428627 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-30 06:40:04.505642 | controller | ok
2025-09-30 06:40:04.569575 | controller | included: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-30 06:40:04.582888 | 
2025-09-30 06:40:04.582972 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-30 06:40:06.049092 | controller -> localhost | Generating public/private rsa key pair.
2025-09-30 06:40:06.049301 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/work/7f0c0fe7e569418082852224b2f04c37_id_rsa.
2025-09-30 06:40:06.049333 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/work/7f0c0fe7e569418082852224b2f04c37_id_rsa.pub.
2025-09-30 06:40:06.049358 | controller -> localhost | The key fingerprint is:
2025-09-30 06:40:06.049378 | controller -> localhost | SHA256:PeXSdhwN9AoM8f3KgKgNskwuX/LkzoC/Anq21Q3Ba0w zuul-build-sshkey
2025-09-30 06:40:06.049396 | controller -> localhost | The key's randomart image is:
2025-09-30 06:40:06.049414 | controller -> localhost | +---[RSA 3072]----+
2025-09-30 06:40:06.049431 | controller -> localhost | |          o. .o  |
2025-09-30 06:40:06.049448 | controller -> localhost | |     .     + . + |
2025-09-30 06:40:06.049465 | controller -> localhost | |      E     = o o|
2025-09-30 06:40:06.049482 | controller -> localhost | |     o o o = o + |
2025-09-30 06:40:06.049499 | controller -> localhost | |    o * S = = + .|
2025-09-30 06:40:06.049516 | controller -> localhost | |.  = = *   + + . |
2025-09-30 06:40:06.049532 | controller -> localhost | |..o B = o     o  |
2025-09-30 06:40:06.049564 | controller -> localhost | |. += O           |
2025-09-30 06:40:06.049582 | controller -> localhost | | o.o+o=          |
2025-09-30 06:40:06.049598 | controller -> localhost | +----[SHA256]-----+
2025-09-30 06:40:06.049646 | controller -> localhost | ok: Runtime: 0:00:00.514608
2025-09-30 06:40:06.068782 | 
2025-09-30 06:40:06.068931 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-30 06:40:06.121367 | controller | ok
2025-09-30 06:40:06.131504 | controller | included: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-30 06:40:06.139315 | 
2025-09-30 06:40:06.139377 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-30 06:40:06.163567 | controller | skipping: Conditional result was False
2025-09-30 06:40:06.169279 | 
2025-09-30 06:40:06.169344 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-30 06:40:06.648892 | controller | changed
2025-09-30 06:40:06.657795 | 
2025-09-30 06:40:06.657966 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-30 06:40:06.958653 | controller | ok
2025-09-30 06:40:06.964879 | 
2025-09-30 06:40:06.964953 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-30 06:40:07.957410 | controller | changed
2025-09-30 06:40:07.965424 | 
2025-09-30 06:40:07.965550 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-30 06:40:08.939128 | controller | changed
2025-09-30 06:40:08.944374 | 
2025-09-30 06:40:08.944436 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-30 06:40:08.988603 | controller | skipping: Conditional result was False
2025-09-30 06:40:08.994335 | 
2025-09-30 06:40:08.994437 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-30 06:40:09.507284 | controller -> localhost | changed
2025-09-30 06:40:09.527224 | 
2025-09-30 06:40:09.527353 | TASK [add-build-sshkey : Add back temp key]
2025-09-30 06:40:09.985414 | controller -> localhost | Identity added: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/work/7f0c0fe7e569418082852224b2f04c37_id_rsa (zuul-build-sshkey)
2025-09-30 06:40:09.985605 | controller -> localhost | ok: Runtime: 0:00:00.013807
2025-09-30 06:40:09.991669 | 
2025-09-30 06:40:09.991733 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-30 06:40:10.442863 | controller | ok
2025-09-30 06:40:10.447656 | 
2025-09-30 06:40:10.447721 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-30 06:40:10.478388 | controller | skipping: Conditional result was False
2025-09-30 06:40:10.488527 | 
2025-09-30 06:40:10.488632 | TASK [include_role : validate-host]
2025-09-30 06:40:10.509429 | controller | ok
2025-09-30 06:40:10.590406 | 
2025-09-30 06:40:10.590525 | TASK [validate-host : Define zuul_info_dir fact]
2025-09-30 06:40:10.662390 | controller | ok
2025-09-30 06:40:10.668487 | 
2025-09-30 06:40:10.668575 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-09-30 06:40:11.071447 | controller -> localhost | ok
2025-09-30 06:40:11.079946 | 
2025-09-30 06:40:11.080077 | TASK [validate-host : Collect information about the host]
2025-09-30 06:40:11.899631 | controller | ok
2025-09-30 06:40:11.916596 | 
2025-09-30 06:40:11.916725 | TASK [validate-host : Sanitize hostname]
2025-09-30 06:40:11.978305 | controller | ok
2025-09-30 06:40:11.983521 | 
2025-09-30 06:40:11.983589 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-09-30 06:40:12.811756 | controller -> localhost | changed
2025-09-30 06:40:12.834455 | 
2025-09-30 06:40:12.834886 | TASK [validate-host : Collect information about zuul worker]
2025-09-30 06:40:13.379763 | controller | ok
2025-09-30 06:40:13.386980 | 
2025-09-30 06:40:13.387101 | TASK [validate-host : Write out all zuul information for each host]
2025-09-30 06:40:14.364078 | controller -> localhost | changed
2025-09-30 06:40:14.376883 | 
2025-09-30 06:40:14.377053 | TASK [include_role : prepare-workspace-openshift]
2025-09-30 06:40:14.401724 | controller | skipping: Conditional result was False
2025-09-30 06:40:14.408045 | 
2025-09-30 06:40:14.408141 | TASK [include_role : remove-zuul-sshkey]
2025-09-30 06:40:14.435326 | controller | skipping: Conditional result was False
2025-09-30 06:40:14.441728 | 
2025-09-30 06:40:14.442034 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 06:40:14.743511 | controller | ok: "logs"
2025-09-30 06:40:14.743747 | controller | ok: All items complete
2025-09-30 06:40:14.743775 | 
2025-09-30 06:40:14.991143 | controller | ok: "artifacts"
2025-09-30 06:40:15.262721 | controller | ok: "docs"
2025-09-30 06:40:15.271516 | 
2025-09-30 06:40:15.271668 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 06:40:15.581254 | controller | changed: "logs"
2025-09-30 06:40:15.836206 | controller | changed: "artifacts"
2025-09-30 06:40:16.099972 | controller | changed: "docs"
2025-09-30 06:40:16.138626 | 
2025-09-30 06:40:16.138771 | PLAY RECAP
2025-09-30 06:40:16.138814 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-09-30 06:40:16.138839 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 06:40:16.138856 | 
2025-09-30 06:40:16.263065 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 06:40:16.264266 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-09-30 06:40:16.843537 | 
2025-09-30 06:40:16.843666 | PLAY [localhost]
2025-09-30 06:40:16.860887 | 
2025-09-30 06:40:16.861025 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-09-30 06:40:17.258392 | localhost | ok
2025-09-30 06:40:17.265485 | 
2025-09-30 06:40:17.265587 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-09-30 06:40:18.086555 | localhost | changed
2025-09-30 06:40:18.107675 | 
2025-09-30 06:40:18.107767 | PLAY [all]
2025-09-30 06:40:18.124002 | 
2025-09-30 06:40:18.124113 | TASK [include_role : prepare-workspace]
2025-09-30 06:40:18.155469 | controller | ok
2025-09-30 06:40:18.171366 | 
2025-09-30 06:40:18.171475 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-30 06:40:18.619441 | controller | ok
2025-09-30 06:40:18.634386 | 
2025-09-30 06:40:18.634549 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-30 06:40:20.565820 | controller | Output suppressed because no_log was given
2025-09-30 06:40:20.579025 | 
2025-09-30 06:40:20.579149 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 06:40:20.841903 | controller | changed: "logs"
2025-09-30 06:40:21.073316 | controller | changed: "artifacts"
2025-09-30 06:40:21.309730 | controller | changed: "docs"
2025-09-30 06:40:21.324757 | 
2025-09-30 06:40:21.324889 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 06:40:21.605186 | controller | changed: "logs"
2025-09-30 06:40:21.605551 | controller | changed: All items complete
2025-09-30 06:40:21.605586 | 
2025-09-30 06:40:21.851956 | controller | changed: "artifacts"
2025-09-30 06:40:22.130767 | controller | changed: "docs"
2025-09-30 06:40:22.151967 | 
2025-09-30 06:40:22.152116 | TASK [Check if worker can sudo]
2025-09-30 06:40:22.702219 | controller | ok: Runtime: 0:00:00.056656
2025-09-30 06:40:22.707568 | 
2025-09-30 06:40:22.707629 | TASK [configure-mirrors : Gather needed facts]
2025-09-30 06:40:22.757065 | controller | skipping: Conditional result was False
2025-09-30 06:40:22.764353 | 
2025-09-30 06:40:22.764470 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-09-30 06:40:22.824452 | controller | ok
2025-09-30 06:40:22.833498 | controller | included: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-09-30 06:40:22.864029 | 
2025-09-30 06:40:22.864152 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-09-30 06:40:23.207765 | controller | ok
2025-09-30 06:40:23.221961 | 
2025-09-30 06:40:23.222208 | LOOP [configure-mirrors : Include OS-specific variables]
2025-09-30 06:40:23.345821 | controller | ok: "/var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-09-30 06:40:23.363408 | 
2025-09-30 06:40:23.363563 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-09-30 06:40:24.346128 | controller | changed
2025-09-30 06:40:24.370430 | 
2025-09-30 06:40:24.370592 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-09-30 06:40:24.435098 | controller | ok: "/var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-09-30 06:40:24.435289 | controller | ok: All items complete
2025-09-30 06:40:24.435356 | 
2025-09-30 06:40:24.475543 | controller | included: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-09-30 06:40:24.482074 | 
2025-09-30 06:40:24.482147 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-09-30 06:40:25.549387 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-09-30 06:40:26.497181 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-09-30 06:40:26.517862 | 
2025-09-30 06:40:26.518011 | TASK [configure-mirrors : Disable deltrarpm]
2025-09-30 06:40:27.061729 | controller | changed: section and option added
2025-09-30 06:40:27.096155 | 
2025-09-30 06:40:27.096311 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-09-30 06:40:27.981507 | controller | 29 files removed
2025-09-30 06:40:27.981926 | controller | ok: Item: dnf clean all Runtime: 0:00:00.500979
2025-09-30 06:40:27.982045 | controller | changed: All items complete
2025-09-30 06:40:27.982104 | 
2025-09-30 06:40:38.275192 | 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 06:40:38.275298 | controller | DNF version: 4.14.0
2025-09-30 06:40:38.275322 | controller | cachedir: /var/cache/dnf
2025-09-30 06:40:38.275341 | controller | Making cache files for all metadata files.
2025-09-30 06:40:38.275359 | controller | baseos: has expired and will be refreshed.
2025-09-30 06:40:38.275376 | controller | appstream: has expired and will be refreshed.
2025-09-30 06:40:38.275392 | controller | crb: has expired and will be refreshed.
2025-09-30 06:40:38.275417 | controller | extras-common: has expired and will be refreshed.
2025-09-30 06:40:38.275433 | controller | repo: downloading from remote: baseos
2025-09-30 06:40:38.275449 | controller | CentOS Stream 9 - BaseOS                         79 MB/s | 8.8 MB     00:00
2025-09-30 06:40:38.275466 | controller | baseos: using metadata from Mon 22 Sep 2025 10:29:43 AM EDT.
2025-09-30 06:40:38.275482 | controller | repo: downloading from remote: appstream
2025-09-30 06:40:38.275498 | controller | CentOS Stream 9 - AppStream                     107 MB/s |  25 MB     00:00
2025-09-30 06:40:38.275513 | controller | appstream: using metadata from Mon 22 Sep 2025 10:33:24 AM EDT.
2025-09-30 06:40:38.275529 | controller | repo: downloading from remote: crb
2025-09-30 06:40:38.275545 | controller | CentOS Stream 9 - CRB                            93 MB/s | 7.1 MB     00:00
2025-09-30 06:40:38.275561 | controller | crb: using metadata from Mon 22 Sep 2025 10:37:51 AM EDT.
2025-09-30 06:40:38.275578 | controller | repo: downloading from remote: extras-common
2025-09-30 06:40:38.275594 | controller | CentOS Stream 9 - Extras packages               1.2 MB/s |  20 kB     00:00
2025-09-30 06:40:38.275610 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT.
2025-09-30 06:40:38.275626 | controller | Last metadata expiration check: 0:00:01 ago on Tue 30 Sep 2025 02:40:36 AM EDT.
2025-09-30 06:40:38.275642 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-09-30 06:40:38.275659 | controller | Completion plugin: Generating completion cache...
2025-09-30 06:40:38.275678 | controller | Metadata cache created.
2025-09-30 06:40:38.275705 | controller | ok: Item: dnf makecache -v Runtime: 0:00:09.997238
2025-09-30 06:40:38.295836 | 
2025-09-30 06:40:38.295946 | PLAY RECAP
2025-09-30 06:40:38.295989 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-09-30 06:40:38.296065 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 06:40:38.296089 | 
2025-09-30 06:40:38.407758 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-09-30 06:40:38.408622 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 06:40:39.039988 | 
2025-09-30 06:40:39.040136 | PLAY [all]
2025-09-30 06:40:39.094957 | 
2025-09-30 06:40:39.095137 | TASK [Install binary dependencies]
2025-09-30 06:40:39.163596 | controller | ok
2025-09-30 06:40:39.191351 | 
2025-09-30 06:40:39.191492 | TASK [bindep : Include find tasks]
2025-09-30 06:40:39.224392 | controller | ok
2025-09-30 06:40:39.234867 | controller | included: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-30 06:40:39.243155 | 
2025-09-30 06:40:39.243317 | TASK [bindep : Look for bindep.txt]
2025-09-30 06:40:39.734490 | controller | ok
2025-09-30 06:40:39.745800 | 
2025-09-30 06:40:39.745911 | TASK [bindep : Define bindep_file fact]
2025-09-30 06:40:39.790401 | controller | ok
2025-09-30 06:40:39.798263 | 
2025-09-30 06:40:39.798371 | TASK [bindep : Look for other-requirements.txt]
2025-09-30 06:40:39.824457 | controller | skipping: Conditional result was False
2025-09-30 06:40:39.831130 | 
2025-09-30 06:40:39.831225 | TASK [bindep : Define bindep_file fact]
2025-09-30 06:40:39.865791 | controller | skipping: Conditional result was False
2025-09-30 06:40:39.871993 | 
2025-09-30 06:40:39.872092 | TASK [bindep : Look for bindep fallback file]
2025-09-30 06:40:39.906846 | controller | skipping: Conditional result was False
2025-09-30 06:40:39.912938 | 
2025-09-30 06:40:39.913067 | TASK [bindep : Define bindep_file fact]
2025-09-30 06:40:39.962914 | controller | skipping: Conditional result was False
2025-09-30 06:40:39.972394 | 
2025-09-30 06:40:39.972528 | TASK [bindep : Include bindep tasks]
2025-09-30 06:40:40.014193 | controller | ok
2025-09-30 06:40:40.024790 | controller | included: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-09-30 06:40:40.033383 | 
2025-09-30 06:40:40.033452 | TASK [bindep : Look for bindep command]
2025-09-30 06:40:40.077997 | controller | skipping: Conditional result was False
2025-09-30 06:40:40.085488 | 
2025-09-30 06:40:40.086455 | TASK [bindep : Check for system bindep]
2025-09-30 06:40:40.628384 | controller | ok: Runtime: 0:00:00.009413
2025-09-30 06:40:40.637655 | 
2025-09-30 06:40:40.637784 | TASK [bindep : Define bindep_command fact]
2025-09-30 06:40:40.665949 | controller | skipping: Conditional result was False
2025-09-30 06:40:40.678005 | 
2025-09-30 06:40:40.678198 | TASK [bindep : Include install tasks]
2025-09-30 06:40:40.719757 | controller | ok
2025-09-30 06:40:40.730142 | controller | included: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-09-30 06:40:40.738988 | 
2025-09-30 06:40:40.739082 | TASK [bindep : Create temp dir for bindep]
2025-09-30 06:40:41.257920 | controller | changed
2025-09-30 06:40:41.271592 | 
2025-09-30 06:40:41.271686 | TASK [Ensure we have pip dependencies]
2025-09-30 06:40:41.328929 | controller | ok
2025-09-30 06:40:41.399264 | 
2025-09-30 06:40:41.405197 | TASK [ensure-pip : Check if pip is installed]
2025-09-30 02:40:41.753045 | controller | /usr/bin/pip3
2025-09-30 02:40:41.794458 | controller | /usr/bin/python3: No module named wheel
2025-09-30 06:40:41.970069 | controller | ok: Runtime: 0:00:00.057382
2025-09-30 06:40:41.984805 | 
2025-09-30 06:40:41.985004 | LOOP [ensure-pip : Install pip from packages]
2025-09-30 06:40:42.029692 | controller | ok: "/var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-09-30 06:40:42.045495 | controller | included: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-09-30 06:40:42.061207 | 
2025-09-30 06:40:42.061296 | TASK [ensure-pip : Install Python 3 pip]
2025-09-30 06:40:44.518670 | controller | changed
2025-09-30 06:40:44.524468 | 
2025-09-30 06:40:44.524534 | TASK [ensure-pip : Check for EPEL repository]
2025-09-30 06:40:44.570064 | controller | skipping: Conditional result was False
2025-09-30 06:40:44.579475 | 
2025-09-30 06:40:44.579610 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-09-30 06:40:44.615318 | controller | skipping: Conditional result was False
2025-09-30 06:40:44.626701 | 
2025-09-30 06:40:44.626866 | TASK [ensure-pip : Install Python 2 pip]
2025-09-30 06:40:44.671994 | controller | skipping: Conditional result was False
2025-09-30 06:40:44.684856 | 
2025-09-30 06:40:44.685002 | TASK [ensure-pip : Ensure setuptools]
2025-09-30 06:40:44.700799 | controller | skipping: Conditional result was False
2025-09-30 06:40:44.713633 | 
2025-09-30 06:40:44.713802 | TASK [ensure-pip : Check for ensurepip module]
2025-09-30 06:40:45.259881 | controller | skipping: Conditional result was False
2025-09-30 06:40:45.276128 | 
2025-09-30 06:40:45.276338 | TASK [ensure-pip : Ensure python3-venv]
2025-09-30 06:40:45.306766 | controller | skipping: Conditional result was False
2025-09-30 06:40:45.322267 | 
2025-09-30 06:40:45.322383 | TASK [ensure-pip : Install pip from source]
2025-09-30 06:40:45.364949 | controller | skipping: Conditional result was False
2025-09-30 06:40:45.384832 | 
2025-09-30 06:40:45.385094 | TASK [ensure-pip : Probe for venv python full path]
2025-09-30 02:40:45.718946 | controller | /usr/bin/python3
2025-09-30 06:40:45.938420 | controller | ok: Runtime: 0:00:00.008221
2025-09-30 06:40:45.951457 | 
2025-09-30 06:40:45.951639 | TASK [ensure-pip : Set host default]
2025-09-30 06:40:46.026855 | controller | ok
2025-09-30 06:40:46.035118 | 
2025-09-30 06:40:46.035227 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-09-30 06:40:46.101636 | controller | ok
2025-09-30 06:40:46.117650 | 
2025-09-30 06:40:46.117764 | TASK [bindep : Install bindep into temporary venv]
2025-09-30 06:40:50.430732 | controller | changed
2025-09-30 06:40:50.438062 | 
2025-09-30 06:40:50.438197 | TASK [bindep : Define bindep_command]
2025-09-30 06:40:50.487655 | controller | ok
2025-09-30 06:40:50.500275 | 
2025-09-30 06:40:50.500506 | LOOP [bindep : Include package tasks]
2025-09-30 06:40:50.583009 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-09-30 06:40:50.583269 | controller | ok: All items complete
2025-09-30 06:40:50.583296 | 
2025-09-30 06:40:50.605902 | controller | included: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-09-30 06:40:50.620037 | 
2025-09-30 06:40:50.620197 | TASK [bindep : Define bindep_run fact]
2025-09-30 06:40:50.687568 | controller | ok
2025-09-30 06:40:50.698868 | 
2025-09-30 06:40:50.698955 | TASK [bindep : Get list of packages to install from bindep]
2025-09-30 02:40:52.394961 | controller | podman
2025-09-30 02:40:52.460271 | controller | python3-jmespath
2025-09-30 02:40:52.460360 | controller | python3-libvirt
2025-09-30 02:40:52.460372 | controller | python3-lxml
2025-09-30 02:40:52.460381 | controller | python3-netaddr
2025-09-30 06:40:52.742758 | controller | ok: Runtime: 0:00:01.459124
2025-09-30 06:40:52.751366 | 
2025-09-30 06:40:52.751456 | TASK [bindep : Install distro packages from bindep]
2025-09-30 06:42:00.501912 | controller | changed
2025-09-30 06:42:00.512009 | 
2025-09-30 06:42:00.512127 | TASK [bindep : Check that packages are installed]
2025-09-30 06:42:02.553193 | controller | ok: Runtime: 0:00:01.357219
2025-09-30 06:42:02.559003 | 
2025-09-30 06:42:02.559087 | TASK [bindep : Fail if we cannot install all packages]
2025-09-30 06:42:02.583164 | controller | skipping: Conditional result was False
2025-09-30 06:42:02.595113 | 
2025-09-30 06:42:02.595250 | TASK [Run test-setup role]
2025-09-30 06:42:02.614607 | controller | ok
2025-09-30 06:42:02.633645 | 
2025-09-30 06:42:02.633728 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-30 06:42:02.866442 | controller | ok
2025-09-30 06:42:02.871701 | 
2025-09-30 06:42:02.871761 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-30 06:42:03.404259 | controller | skipping: Conditional result was False
2025-09-30 06:42:03.429334 | 
2025-09-30 06:42:03.429413 | TASK [bindep : Remove bindep temp dir]
2025-09-30 06:42:03.806639 | controller | ok
2025-09-30 06:42:03.819550 | 
2025-09-30 06:42:03.819604 | PLAY RECAP
2025-09-30 06:42:03.819648 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-09-30 06:42:03.819668 | 
2025-09-30 06:42:03.932174 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 06:42:03.933027 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-09-30 06:42:04.481762 | 
2025-09-30 06:42:04.481857 | PLAY [all]
2025-09-30 06:42:04.510310 | 
2025-09-30 06:42:04.510411 | TASK [Abort when test_command variable is undefined]
2025-09-30 06:42:04.544893 | controller | skipping: Conditional result was False
2025-09-30 06:42:04.550539 | 
2025-09-30 06:42:04.550613 | TASK [Convert test_command to list]
2025-09-30 06:42:04.584518 | controller | skipping: Conditional result was False
2025-09-30 06:42:04.590902 | 
2025-09-30 06:42:04.590968 | TASK [Use test_command list]
2025-09-30 06:42:04.639767 | controller | ok
2025-09-30 06:42:04.644931 | 
2025-09-30 06:42:04.644991 | LOOP [Run test_command]
2025-09-30 06:42:05.048162 | controller | no check to run
2025-09-30 06:42:05.048346 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.008014
2025-09-30 06:42:05.078846 | 
2025-09-30 06:42:05.078962 | PLAY RECAP
2025-09-30 06:42:05.079025 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-30 06:42:05.079142 | 
2025-09-30 06:42:05.186443 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-09-30 06:42:05.187330 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 06:42:05.767218 | 
2025-09-30 06:42:05.767319 | PLAY [all]
2025-09-30 06:42:05.787594 | 
2025-09-30 06:42:05.787671 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-30 06:42:06.137916 | controller | changed: non-zero return code
2025-09-30 06:42:06.143958 | 
2025-09-30 06:42:06.144097 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-30 06:42:06.158490 | controller | skipping: Conditional result was False
2025-09-30 06:42:06.165501 | 
2025-09-30 06:42:06.165612 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-30 06:42:06.198630 | 
2025-09-30 06:42:06.198790 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-30 06:42:06.219768 | 
2025-09-30 06:42:06.219996 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-30 06:42:06.236531 | controller | skipping: Conditional result was False
2025-09-30 06:42:06.243969 | 
2025-09-30 06:42:06.244084 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-30 06:42:06.275323 | 
2025-09-30 06:42:06.275485 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-30 06:42:06.300715 | controller | skipping: Conditional result was False
2025-09-30 06:42:06.306308 | 
2025-09-30 06:42:06.306382 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-30 06:42:06.319941 | controller | skipping: Conditional result was False
2025-09-30 06:42:06.326398 | 
2025-09-30 06:42:06.326478 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-30 06:42:06.340189 | controller | skipping: Conditional result was False
2025-09-30 06:42:06.364216 | 
2025-09-30 06:42:06.364340 | PLAY RECAP
2025-09-30 06:42:06.364385 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-30 06:42:06.364405 | 
2025-09-30 06:42:06.458847 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 06:42:06.459705 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 06:42:07.036400 | 
2025-09-30 06:42:07.036516 | PLAY [all]
2025-09-30 06:42:07.055701 | 
2025-09-30 06:42:07.055807 | TASK [include_role : fetch-output]
2025-09-30 06:42:07.096479 | controller | ok
2025-09-30 06:42:07.113568 | 
2025-09-30 06:42:07.113651 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-30 06:42:07.168789 | controller | skipping: Conditional result was False
2025-09-30 06:42:07.181452 | 
2025-09-30 06:42:07.181596 | TASK [fetch-output : Set log path for single node]
2025-09-30 06:42:07.245546 | controller | ok
2025-09-30 06:42:07.253947 | 
2025-09-30 06:42:07.254079 | LOOP [fetch-output : Ensure local output dirs]
2025-09-30 06:42:07.696305 | controller -> localhost | ok: "/var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/work/logs"
2025-09-30 06:42:07.904649 | controller -> localhost | changed: "/var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/work/artifacts"
2025-09-30 06:42:08.110833 | controller -> localhost | changed: "/var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/work/docs"
2025-09-30 06:42:08.126431 | 
2025-09-30 06:42:08.126506 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-30 06:42:08.764916 | controller | changed: .d..t...... ./
2025-09-30 06:42:08.765139 | controller | changed: All items complete
2025-09-30 06:42:08.765168 | 
2025-09-30 06:42:09.299991 | controller | changed: .d..t...... ./
2025-09-30 06:42:09.832843 | controller | changed: .d..t...... ./
2025-09-30 06:42:09.852822 | 
2025-09-30 06:42:09.852935 | TASK [include_role : fetch-output-openshift]
2025-09-30 06:42:09.867290 | controller | skipping: Conditional result was False
2025-09-30 06:42:09.873534 | 
2025-09-30 06:42:09.873607 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-30 06:42:10.283826 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.012079
2025-09-30 06:42:10.495593 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.007847
2025-09-30 06:42:10.528667 | 
2025-09-30 06:42:10.528813 | PLAY [all]
2025-09-30 06:42:10.542722 | 
2025-09-30 06:42:10.542786 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-09-30 06:42:11.021347 | controller | changed
2025-09-30 06:42:11.064687 | 
2025-09-30 06:42:11.064761 | PLAY RECAP
2025-09-30 06:42:11.064814 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-30 06:42:11.064841 | 
2025-09-30 06:42:11.192284 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 06:42:11.193123 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-09-30 06:42:11.806739 | 
2025-09-30 06:42:11.806868 | PLAY [localhost]
2025-09-30 06:42:11.830115 | 
2025-09-30 06:42:11.830250 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-30 06:42:12.195061 | localhost | changed
2025-09-30 06:42:12.200070 | 
2025-09-30 06:42:12.200147 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-30 06:42:12.227550 | localhost | ok
2025-09-30 06:42:12.235426 | 
2025-09-30 06:42:12.235489 | TASK [add-fileserver : Create SSH private key tempfile]
2025-09-30 06:42:12.598346 | localhost | changed
2025-09-30 06:42:12.603223 | 
2025-09-30 06:42:12.603287 | TASK [add-fileserver : Create SSH private key from secret]
2025-09-30 06:42:13.213390 | localhost | changed
2025-09-30 06:42:13.218610 | 
2025-09-30 06:42:13.218732 | TASK [add-fileserver : Add fileserver ssh key]
2025-09-30 06:42:13.625124 | localhost | Identity added: /var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/work/tmp/ansible._v2rjphq (/var/lib/zuul/builds/7f0c0fe7e569418082852224b2f04c37/work/tmp/ansible._v2rjphq)
2025-09-30 06:42:13.625306 | localhost | ok: Runtime: 0:00:00.019140
2025-09-30 06:42:13.629607 | 
2025-09-30 06:42:13.629672 | TASK [add-fileserver : Remove SSH private key from disk]
2025-09-30 06:42:13.902350 | localhost | ok: Runtime: 0:00:00.010919
2025-09-30 06:42:13.912767 | 
2025-09-30 06:42:13.912903 | TASK [add-fileserver : Add fileserver to inventory]
2025-09-30 06:42:13.979072 | localhost | changed
2025-09-30 06:42:13.989342 | 
2025-09-30 06:42:13.989468 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-09-30 06:42:14.391779 | localhost | changed
2025-09-30 06:42:14.419413 | 
2025-09-30 06:42:14.419504 | PLAY [localhost]
2025-09-30 06:42:14.430751 | 
2025-09-30 06:42:14.430821 | TASK [Generate bulk log download script]
2025-09-30 06:42:14.449812 | localhost | ok
2025-09-30 06:42:14.461177 | 
2025-09-30 06:42:14.461248 | TASK [local-log-download : Check API endpoint is defined]
2025-09-30 06:42:14.489408 | localhost | ok: All assertions passed
2025-09-30 06:42:14.493879 | 
2025-09-30 06:42:14.493936 | TASK [local-log-download : Create download script]
2025-09-30 06:42:14.867178 | localhost -> localhost | changed
2025-09-30 06:42:14.886545 | 
2025-09-30 06:42:14.886686 | TASK [Register quick-download link]
2025-09-30 06:42:14.911945 | localhost | ok
2025-09-30 06:42:14.973310 | 
2025-09-30 06:42:14.973433 | PLAY [logserver.rdoproject.org]
2025-09-30 06:42:14.986840 | 
2025-09-30 06:42:14.986930 | TASK [Set zuul-log-path fact]
2025-09-30 06:42:15.006061 | logserver.rdoproject.org | ok
2025-09-30 06:42:15.019107 | 
2025-09-30 06:42:15.019207 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 06:42:15.058057 | logserver.rdoproject.org | ok
2025-09-30 06:42:15.066077 | 
2025-09-30 06:42:15.066163 | TASK [upload-logs : Create log directories]
2025-09-30 06:42:15.780985 | logserver.rdoproject.org | changed
2025-09-30 06:42:15.785619 | 
2025-09-30 06:42:15.785700 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-09-30 06:42:16.119160 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.008405
2025-09-30 06:42:16.128527 | 
2025-09-30 06:42:16.128652 | TASK [upload-logs : Upload logs to log server]
2025-09-30 06:42:16.893757 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-09-30 06:42:16.900634 | 
2025-09-30 06:42:16.900849 | LOOP [upload-logs : Compress console log and json output]
2025-09-30 06:42:16.971537 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 06:42:16.983165 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 06:42:16.997483 | 
2025-09-30 06:42:16.997659 | LOOP [upload-logs : Upload compressed console log and json output]
2025-09-30 06:42:17.047521 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 06:42:17.047773 | 
2025-09-30 06:42:17.051002 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 06:42:17.063059 | 
2025-09-30 06:42:17.063228 | LOOP [upload-logs : Upload console log and json output]