2025-09-30 07:28:38.247511 | Job console starting...
2025-09-30 07:28:38.258231 | Updating repositories
2025-09-30 07:28:38.297380 | Preparing job workspace
2025-09-30 07:28:42.022965 | Running Ansible setup...
2025-09-30 07:28:45.986345 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 07:28:46.560599 | 
2025-09-30 07:28:46.560703 | PLAY [localhost]
2025-09-30 07:28:46.569245 | 
2025-09-30 07:28:46.569312 | TASK [Gathering Facts]
2025-09-30 07:28:47.585123 | localhost | ok
2025-09-30 07:28:47.618578 | 
2025-09-30 07:28:47.618795 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-30 07:28:48.104595 | localhost -> localhost | changed
2025-09-30 07:28:48.110019 | 
2025-09-30 07:28:48.110095 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-30 07:28:48.955979 | localhost -> localhost | changed
2025-09-30 07:28:48.988489 | 
2025-09-30 07:28:48.988768 | TASK [Setup log path fact]
2025-09-30 07:28:49.014299 | localhost | ok
2025-09-30 07:28:49.038604 | 
2025-09-30 07:28:49.038695 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 07:28:49.081055 | localhost | ok
2025-09-30 07:28:49.097590 | 
2025-09-30 07:28:49.097783 | TASK [emit-job-header : Print job information]
2025-09-30 07:28:49.153903 | # Job Information
2025-09-30 07:28:49.154160 | Ansible Version: 2.15.12
2025-09-30 07:28:49.154218 | Job: cifmw-molecule-federation
2025-09-30 07:28:49.154262 | Pipeline: github-check
2025-09-30 07:28:49.154300 | Executor: ze03.softwarefactory-project.io
2025-09-30 07:28:49.154339 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3307
2025-09-30 07:28:49.154380 | Log URL (when completed): https://logserver.rdoproject.org/37c/rdoproject.org/37c64e4c23984c58a3a801c8fde8fd2a/
2025-09-30 07:28:49.154418 | Event ID: ebb029e0-9dce-11f0-9730-560a3bbe051a
2025-09-30 07:28:49.171965 | 
2025-09-30 07:28:49.172098 | LOOP [emit-job-header : Print node information]
2025-09-30 07:28:49.289591 | localhost | ok:
2025-09-30 07:28:49.289819 | localhost | # Node Information
2025-09-30 07:28:49.289847 | localhost | Inventory Hostname: controller
2025-09-30 07:28:49.289868 | localhost | Hostname: np0005461980
2025-09-30 07:28:49.289887 | localhost | Username: zuul
2025-09-30 07:28:49.289906 | localhost | Distro: CentOS 9
2025-09-30 07:28:49.289924 | localhost | Provider: vexxhost-nodepool-tripleo
2025-09-30 07:28:49.289941 | localhost | Region: RegionOne
2025-09-30 07:28:49.289957 | localhost | Label: cloud-centos-9-stream-tripleo
2025-09-30 07:28:49.289973 | localhost | Product Name: OpenStack Nova
2025-09-30 07:28:49.289989 | localhost | Interface IP: 38.102.83.192
2025-09-30 07:28:49.316321 | 
2025-09-30 07:28:49.316448 | PLAY [all]
2025-09-30 07:28:49.322779 | 
2025-09-30 07:28:49.322838 | TASK [Gather network facts]
2025-09-30 07:28:49.882089 | controller | ok
2025-09-30 07:28:49.930221 | 
2025-09-30 07:28:49.930332 | TASK [include_role : start-zuul-console]
2025-09-30 07:28:49.951755 | controller | ok
2025-09-30 07:28:49.968900 | 
2025-09-30 07:28:49.969003 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-30 07:28:50.415565 | controller | ok
2025-09-30 07:28:50.442105 | 
2025-09-30 07:28:50.442216 | TASK [include_role : add-build-sshkey]
2025-09-30 07:28:50.473190 | controller | ok
2025-09-30 07:28:50.493321 | 
2025-09-30 07:28:50.493409 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-30 07:28:50.772566 | controller -> localhost | ok
2025-09-30 07:28:50.785690 | 
2025-09-30 07:28:50.785890 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-30 07:28:50.825363 | controller | ok
2025-09-30 07:28:50.849908 | controller | included: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-30 07:28:50.857856 | 
2025-09-30 07:28:50.857942 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-30 07:28:51.533678 | controller -> localhost | Generating public/private rsa key pair.
2025-09-30 07:28:51.533895 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/work/37c64e4c23984c58a3a801c8fde8fd2a_id_rsa.
2025-09-30 07:28:51.533933 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/work/37c64e4c23984c58a3a801c8fde8fd2a_id_rsa.pub.
2025-09-30 07:28:51.533958 | controller -> localhost | The key fingerprint is:
2025-09-30 07:28:51.533980 | controller -> localhost | SHA256:wfPmN0B4ZrlaM69DatfrmiHRJmzw4BcfhACz78wEW/o zuul-build-sshkey
2025-09-30 07:28:51.533999 | controller -> localhost | The key's randomart image is:
2025-09-30 07:28:51.534073 | controller -> localhost | +---[RSA 3072]----+
2025-09-30 07:28:51.534094 | controller -> localhost | |    o... ..      |
2025-09-30 07:28:51.534113 | controller -> localhost | |     o ..o .     |
2025-09-30 07:28:51.534132 | controller -> localhost | |    o + * B      |
2025-09-30 07:28:51.534150 | controller -> localhost | |     B = % o     |
2025-09-30 07:28:51.534167 | controller -> localhost | |    o + S %      |
2025-09-30 07:28:51.534184 | controller -> localhost | |     * o O.=     |
2025-09-30 07:28:51.534201 | controller -> localhost | |      E ooo.+    |
2025-09-30 07:28:51.534218 | controller -> localhost | |        o.o=..   |
2025-09-30 07:28:51.534235 | controller -> localhost | |       . .++o.   |
2025-09-30 07:28:51.534251 | controller -> localhost | +----[SHA256]-----+
2025-09-30 07:28:51.534293 | controller -> localhost | ok: Runtime: 0:00:00.237154
2025-09-30 07:28:51.540237 | 
2025-09-30 07:28:51.540303 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-30 07:28:51.569434 | controller | ok
2025-09-30 07:28:51.579341 | controller | included: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-30 07:28:51.587608 | 
2025-09-30 07:28:51.587685 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-30 07:28:51.612228 | controller | skipping: Conditional result was False
2025-09-30 07:28:51.622216 | 
2025-09-30 07:28:51.622334 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-30 07:28:52.081086 | controller | changed
2025-09-30 07:28:52.086290 | 
2025-09-30 07:28:52.086355 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-30 07:28:52.387588 | controller | ok
2025-09-30 07:28:52.401000 | 
2025-09-30 07:28:52.401152 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-30 07:28:53.395304 | controller | changed
2025-09-30 07:28:53.407259 | 
2025-09-30 07:28:53.407394 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-30 07:28:54.439553 | controller | changed
2025-09-30 07:28:54.450271 | 
2025-09-30 07:28:54.450416 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-30 07:28:54.478229 | controller | skipping: Conditional result was False
2025-09-30 07:28:54.490136 | 
2025-09-30 07:28:54.490266 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-30 07:28:54.944011 | controller -> localhost | changed
2025-09-30 07:28:54.955575 | 
2025-09-30 07:28:54.955654 | TASK [add-build-sshkey : Add back temp key]
2025-09-30 07:28:55.243767 | controller -> localhost | Identity added: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/work/37c64e4c23984c58a3a801c8fde8fd2a_id_rsa (zuul-build-sshkey)
2025-09-30 07:28:55.243966 | controller -> localhost | ok: Runtime: 0:00:00.013185
2025-09-30 07:28:55.253064 | 
2025-09-30 07:28:55.253196 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-30 07:28:55.666178 | controller | ok
2025-09-30 07:28:55.687549 | 
2025-09-30 07:28:55.687701 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-30 07:28:55.726570 | controller | skipping: Conditional result was False
2025-09-30 07:28:55.747978 | 
2025-09-30 07:28:55.748113 | TASK [include_role : validate-host]
2025-09-30 07:28:55.782047 | controller | ok
2025-09-30 07:28:55.809699 | 
2025-09-30 07:28:55.809890 | TASK [validate-host : Define zuul_info_dir fact]
2025-09-30 07:28:55.839063 | controller | ok
2025-09-30 07:28:55.844172 | 
2025-09-30 07:28:55.844233 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-09-30 07:28:56.102062 | controller -> localhost | ok
2025-09-30 07:28:56.115866 | 
2025-09-30 07:28:56.116015 | TASK [validate-host : Collect information about the host]
2025-09-30 07:28:57.031214 | controller | ok
2025-09-30 07:28:57.048503 | 
2025-09-30 07:28:57.048651 | TASK [validate-host : Sanitize hostname]
2025-09-30 07:28:57.110906 | controller | ok
2025-09-30 07:28:57.120390 | 
2025-09-30 07:28:57.120591 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-09-30 07:28:57.584455 | controller -> localhost | changed
2025-09-30 07:28:57.590525 | 
2025-09-30 07:28:57.590591 | TASK [validate-host : Collect information about zuul worker]
2025-09-30 07:28:58.058495 | controller | ok
2025-09-30 07:28:58.063439 | 
2025-09-30 07:28:58.063504 | TASK [validate-host : Write out all zuul information for each host]
2025-09-30 07:28:58.537398 | controller -> localhost | changed
2025-09-30 07:28:58.558107 | 
2025-09-30 07:28:58.558193 | TASK [include_role : prepare-workspace-openshift]
2025-09-30 07:28:58.572963 | controller | skipping: Conditional result was False
2025-09-30 07:28:58.581813 | 
2025-09-30 07:28:58.581914 | TASK [include_role : remove-zuul-sshkey]
2025-09-30 07:28:58.596392 | controller | skipping: Conditional result was False
2025-09-30 07:28:58.603635 | 
2025-09-30 07:28:58.603764 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 07:28:58.914980 | controller | ok: "logs"
2025-09-30 07:28:58.915255 | controller | ok: All items complete
2025-09-30 07:28:58.915294 | 
2025-09-30 07:28:59.177565 | controller | ok: "artifacts"
2025-09-30 07:28:59.454301 | controller | ok: "docs"
2025-09-30 07:28:59.479306 | 
2025-09-30 07:28:59.479501 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 07:28:59.772763 | controller | changed: "logs"
2025-09-30 07:29:00.070202 | controller | changed: "artifacts"
2025-09-30 07:29:00.323823 | controller | changed: "docs"
2025-09-30 07:29:00.376850 | 
2025-09-30 07:29:00.376981 | PLAY RECAP
2025-09-30 07:29:00.377042 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-09-30 07:29:00.377079 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 07:29:00.377105 | 
2025-09-30 07:29:00.508552 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 07:29:00.510560 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-09-30 07:29:01.113918 | 
2025-09-30 07:29:01.114048 | PLAY [localhost]
2025-09-30 07:29:01.130549 | 
2025-09-30 07:29:01.130677 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-09-30 07:29:01.617013 | localhost | ok
2025-09-30 07:29:01.632155 | 
2025-09-30 07:29:01.632395 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-09-30 07:29:02.331064 | localhost | changed
2025-09-30 07:29:02.352122 | 
2025-09-30 07:29:02.352301 | PLAY [all]
2025-09-30 07:29:02.371480 | 
2025-09-30 07:29:02.371648 | TASK [include_role : prepare-workspace]
2025-09-30 07:29:02.394217 | controller | ok
2025-09-30 07:29:02.408968 | 
2025-09-30 07:29:02.409071 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-30 07:29:02.880924 | controller | ok
2025-09-30 07:29:02.896008 | 
2025-09-30 07:29:02.896181 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-30 07:29:04.722207 | controller | Output suppressed because no_log was given
2025-09-30 07:29:04.739977 | 
2025-09-30 07:29:04.740129 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 07:29:05.047144 | controller | changed: "logs"
2025-09-30 07:29:05.310227 | controller | changed: "artifacts"
2025-09-30 07:29:05.568412 | controller | changed: "docs"
2025-09-30 07:29:05.589444 | 
2025-09-30 07:29:05.589612 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 07:29:05.903780 | controller | changed: "logs"
2025-09-30 07:29:05.904632 | controller | changed: All items complete
2025-09-30 07:29:05.905076 | 
2025-09-30 07:29:06.155306 | controller | changed: "artifacts"
2025-09-30 07:29:06.452895 | controller | changed: "docs"
2025-09-30 07:29:06.471143 | 
2025-09-30 07:29:06.471444 | TASK [Check if worker can sudo]
2025-09-30 07:29:07.531902 | controller | ok: Runtime: 0:00:00.067743
2025-09-30 07:29:07.548311 | 
2025-09-30 07:29:07.548579 | TASK [configure-mirrors : Gather needed facts]
2025-09-30 07:29:07.617565 | controller | skipping: Conditional result was False
2025-09-30 07:29:07.629691 | 
2025-09-30 07:29:07.629938 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-09-30 07:29:07.687911 | controller | ok
2025-09-30 07:29:07.699981 | controller | included: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-09-30 07:29:07.736175 | 
2025-09-30 07:29:07.736332 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-09-30 07:29:08.049323 | controller | ok
2025-09-30 07:29:08.062577 | 
2025-09-30 07:29:08.062709 | LOOP [configure-mirrors : Include OS-specific variables]
2025-09-30 07:29:08.159709 | controller | ok: "/var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-09-30 07:29:08.174707 | 
2025-09-30 07:29:08.174890 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-09-30 07:29:09.222201 | controller | changed
2025-09-30 07:29:09.227789 | 
2025-09-30 07:29:09.227852 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-09-30 07:29:09.279253 | controller | ok: "/var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-09-30 07:29:09.279464 | controller | ok: All items complete
2025-09-30 07:29:09.279500 | 
2025-09-30 07:29:09.340692 | controller | included: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-09-30 07:29:09.349459 | 
2025-09-30 07:29:09.349526 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-09-30 07:29:10.474771 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-09-30 07:29:11.521054 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-09-30 07:29:11.535916 | 
2025-09-30 07:29:11.536026 | TASK [configure-mirrors : Disable deltrarpm]
2025-09-30 07:29:12.067046 | controller | changed: section and option added
2025-09-30 07:29:12.106058 | 
2025-09-30 07:29:12.106178 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-09-30 07:29:13.035683 | controller | 29 files removed
2025-09-30 07:29:13.036981 | controller | ok: Item: dnf clean all Runtime: 0:00:00.554358
2025-09-30 07:29:13.037086 | controller | changed: All items complete
2025-09-30 07:29:13.037134 | 
2025-09-30 07:29:23.192317 | 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 07:29:23.192510 | controller | DNF version: 4.14.0
2025-09-30 07:29:23.192588 | controller | cachedir: /var/cache/dnf
2025-09-30 07:29:23.192655 | controller | Making cache files for all metadata files.
2025-09-30 07:29:23.192718 | controller | baseos: has expired and will be refreshed.
2025-09-30 07:29:23.192838 | controller | appstream: has expired and will be refreshed.
2025-09-30 07:29:23.192901 | controller | crb: has expired and will be refreshed.
2025-09-30 07:29:23.192983 | controller | extras-common: has expired and will be refreshed.
2025-09-30 07:29:23.193051 | controller | repo: downloading from remote: baseos
2025-09-30 07:29:23.193119 | controller | CentOS Stream 9 - BaseOS                         74 MB/s | 8.8 MB     00:00
2025-09-30 07:29:23.193190 | controller | baseos: using metadata from Mon 22 Sep 2025 10:29:43 AM EDT.
2025-09-30 07:29:23.193257 | controller | repo: downloading from remote: appstream
2025-09-30 07:29:23.193320 | controller | CentOS Stream 9 - AppStream                      99 MB/s |  25 MB     00:00
2025-09-30 07:29:23.193381 | controller | appstream: using metadata from Mon 22 Sep 2025 10:33:24 AM EDT.
2025-09-30 07:29:23.193441 | controller | repo: downloading from remote: crb
2025-09-30 07:29:23.193500 | controller | CentOS Stream 9 - CRB                            73 MB/s | 7.1 MB     00:00
2025-09-30 07:29:23.193798 | controller | crb: using metadata from Mon 22 Sep 2025 10:37:51 AM EDT.
2025-09-30 07:29:23.193911 | controller | repo: downloading from remote: extras-common
2025-09-30 07:29:23.193993 | controller | CentOS Stream 9 - Extras packages               1.3 MB/s |  20 kB     00:00
2025-09-30 07:29:23.194067 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT.
2025-09-30 07:29:23.194139 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-09-30 07:29:23.194216 | controller | Completion plugin: Generating completion cache...
2025-09-30 07:29:23.194290 | controller | Metadata cache created.
2025-09-30 07:29:23.194388 | controller | ok: Item: dnf makecache -v Runtime: 0:00:09.833878
2025-09-30 07:29:23.221605 | 
2025-09-30 07:29:23.221693 | PLAY RECAP
2025-09-30 07:29:23.221784 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-09-30 07:29:23.221836 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 07:29:23.221864 | 
2025-09-30 07:29:23.340958 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-09-30 07:29:23.341756 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 07:29:23.906258 | 
2025-09-30 07:29:23.906368 | PLAY [all]
2025-09-30 07:29:23.928069 | 
2025-09-30 07:29:23.928185 | TASK [Install binary dependencies]
2025-09-30 07:29:23.977705 | controller | ok
2025-09-30 07:29:23.996472 | 
2025-09-30 07:29:23.996557 | TASK [bindep : Include find tasks]
2025-09-30 07:29:24.025999 | controller | ok
2025-09-30 07:29:24.041644 | controller | included: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-30 07:29:24.056456 | 
2025-09-30 07:29:24.056624 | TASK [bindep : Look for bindep.txt]
2025-09-30 07:29:24.450944 | controller | ok
2025-09-30 07:29:24.465134 | 
2025-09-30 07:29:24.465277 | TASK [bindep : Define bindep_file fact]
2025-09-30 07:29:24.512571 | controller | ok
2025-09-30 07:29:24.524127 | 
2025-09-30 07:29:24.524268 | TASK [bindep : Look for other-requirements.txt]
2025-09-30 07:29:24.550688 | controller | skipping: Conditional result was False
2025-09-30 07:29:24.563003 | 
2025-09-30 07:29:24.563171 | TASK [bindep : Define bindep_file fact]
2025-09-30 07:29:24.599768 | controller | skipping: Conditional result was False
2025-09-30 07:29:24.612287 | 
2025-09-30 07:29:24.612430 | TASK [bindep : Look for bindep fallback file]
2025-09-30 07:29:24.648699 | controller | skipping: Conditional result was False
2025-09-30 07:29:24.662009 | 
2025-09-30 07:29:24.662160 | TASK [bindep : Define bindep_file fact]
2025-09-30 07:29:24.699241 | controller | skipping: Conditional result was False
2025-09-30 07:29:24.711472 | 
2025-09-30 07:29:24.711612 | TASK [bindep : Include bindep tasks]
2025-09-30 07:29:24.761810 | controller | ok
2025-09-30 07:29:24.777404 | controller | included: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-09-30 07:29:24.794468 | 
2025-09-30 07:29:24.794551 | TASK [bindep : Look for bindep command]
2025-09-30 07:29:24.819214 | controller | skipping: Conditional result was False
2025-09-30 07:29:24.828561 | 
2025-09-30 07:29:24.828686 | TASK [bindep : Check for system bindep]
2025-09-30 07:29:25.368599 | controller | ok: Runtime: 0:00:00.006540
2025-09-30 07:29:25.380811 | 
2025-09-30 07:29:25.380953 | TASK [bindep : Define bindep_command fact]
2025-09-30 07:29:25.407544 | controller | skipping: Conditional result was False
2025-09-30 07:29:25.420781 | 
2025-09-30 07:29:25.420936 | TASK [bindep : Include install tasks]
2025-09-30 07:29:25.469076 | controller | ok
2025-09-30 07:29:25.485191 | controller | included: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-09-30 07:29:25.499611 | 
2025-09-30 07:29:25.499718 | TASK [bindep : Create temp dir for bindep]
2025-09-30 07:29:25.885567 | controller | changed
2025-09-30 07:29:25.891021 | 
2025-09-30 07:29:25.891101 | TASK [Ensure we have pip dependencies]
2025-09-30 07:29:25.914949 | controller | ok
2025-09-30 07:29:25.949790 | 
2025-09-30 07:29:25.949925 | TASK [ensure-pip : Check if pip is installed]
2025-09-30 03:29:26.285218 | controller | /usr/bin/pip3
2025-09-30 03:29:26.326106 | controller | /usr/bin/python3: No module named wheel
2025-09-30 07:29:26.484897 | controller | ok: Runtime: 0:00:00.055918
2025-09-30 07:29:26.497409 | 
2025-09-30 07:29:26.497612 | LOOP [ensure-pip : Install pip from packages]
2025-09-30 07:29:26.555210 | controller | ok: "/var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-09-30 07:29:26.582532 | controller | included: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-09-30 07:29:26.608864 | 
2025-09-30 07:29:26.609055 | TASK [ensure-pip : Install Python 3 pip]
2025-09-30 07:29:29.179902 | controller | changed
2025-09-30 07:29:29.191171 | 
2025-09-30 07:29:29.191298 | TASK [ensure-pip : Check for EPEL repository]
2025-09-30 07:29:29.238080 | controller | skipping: Conditional result was False
2025-09-30 07:29:29.252577 | 
2025-09-30 07:29:29.252803 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-09-30 07:29:29.310536 | controller | skipping: Conditional result was False
2025-09-30 07:29:29.324491 | 
2025-09-30 07:29:29.324661 | TASK [ensure-pip : Install Python 2 pip]
2025-09-30 07:29:29.372621 | controller | skipping: Conditional result was False
2025-09-30 07:29:29.393891 | 
2025-09-30 07:29:29.394114 | TASK [ensure-pip : Ensure setuptools]
2025-09-30 07:29:29.419744 | controller | skipping: Conditional result was False
2025-09-30 07:29:29.428693 | 
2025-09-30 07:29:29.428808 | TASK [ensure-pip : Check for ensurepip module]
2025-09-30 07:29:29.970764 | controller | skipping: Conditional result was False
2025-09-30 07:29:29.986917 | 
2025-09-30 07:29:29.987128 | TASK [ensure-pip : Ensure python3-venv]
2025-09-30 07:29:30.015272 | controller | skipping: Conditional result was False
2025-09-30 07:29:30.040532 | 
2025-09-30 07:29:30.040770 | TASK [ensure-pip : Install pip from source]
2025-09-30 07:29:30.069423 | controller | skipping: Conditional result was False
2025-09-30 07:29:30.083606 | 
2025-09-30 07:29:30.083931 | TASK [ensure-pip : Probe for venv python full path]
2025-09-30 03:29:30.396024 | controller | /usr/bin/python3
2025-09-30 07:29:30.626138 | controller | ok: Runtime: 0:00:00.006376
2025-09-30 07:29:30.639288 | 
2025-09-30 07:29:30.639491 | TASK [ensure-pip : Set host default]
2025-09-30 07:29:30.718972 | controller | ok
2025-09-30 07:29:30.730558 | 
2025-09-30 07:29:30.730699 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-09-30 07:29:30.794149 | controller | ok
2025-09-30 07:29:30.820563 | 
2025-09-30 07:29:30.820810 | TASK [bindep : Install bindep into temporary venv]
2025-09-30 07:29:34.968032 | controller | changed
2025-09-30 07:29:34.980799 | 
2025-09-30 07:29:34.980969 | TASK [bindep : Define bindep_command]
2025-09-30 07:29:35.041978 | controller | ok
2025-09-30 07:29:35.054291 | 
2025-09-30 07:29:35.054478 | LOOP [bindep : Include package tasks]
2025-09-30 07:29:35.125980 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-09-30 07:29:35.126348 | controller | ok: All items complete
2025-09-30 07:29:35.126392 | 
2025-09-30 07:29:35.151887 | controller | included: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-09-30 07:29:35.175370 | 
2025-09-30 07:29:35.175552 | TASK [bindep : Define bindep_run fact]
2025-09-30 07:29:35.209070 | controller | ok
2025-09-30 07:29:35.216604 | 
2025-09-30 07:29:35.216715 | TASK [bindep : Get list of packages to install from bindep]
2025-09-30 03:29:36.556620 | controller | podman
2025-09-30 03:29:36.605814 | controller | python3-jmespath
2025-09-30 03:29:36.605850 | controller | python3-libvirt
2025-09-30 03:29:36.605860 | controller | python3-lxml
2025-09-30 03:29:36.605870 | controller | python3-netaddr
2025-09-30 07:29:36.759971 | controller | ok: Runtime: 0:00:01.080378
2025-09-30 07:29:36.774103 | 
2025-09-30 07:29:36.774297 | TASK [bindep : Install distro packages from bindep]
2025-09-30 07:30:37.965256 | controller | changed
2025-09-30 07:30:37.987584 | 
2025-09-30 07:30:37.987873 | TASK [bindep : Check that packages are installed]
2025-09-30 07:30:40.038434 | controller | ok: Runtime: 0:00:01.302976
2025-09-30 07:30:40.044712 | 
2025-09-30 07:30:40.044812 | TASK [bindep : Fail if we cannot install all packages]
2025-09-30 07:30:40.079285 | controller | skipping: Conditional result was False
2025-09-30 07:30:40.091949 | 
2025-09-30 07:30:40.092086 | TASK [Run test-setup role]
2025-09-30 07:30:40.143616 | controller | ok
2025-09-30 07:30:40.175512 | 
2025-09-30 07:30:40.175668 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-30 07:30:40.474978 | controller | ok
2025-09-30 07:30:40.492950 | 
2025-09-30 07:30:40.493201 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-30 07:30:41.049848 | controller | skipping: Conditional result was False
2025-09-30 07:30:41.093008 | 
2025-09-30 07:30:41.093171 | TASK [bindep : Remove bindep temp dir]
2025-09-30 07:30:41.526401 | controller | ok
2025-09-30 07:30:41.537631 | 
2025-09-30 07:30:41.537756 | PLAY RECAP
2025-09-30 07:30:41.537814 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-09-30 07:30:41.537836 | 
2025-09-30 07:30:41.649450 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 07:30:41.650442 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-09-30 07:30:42.221563 | 
2025-09-30 07:30:42.221693 | PLAY [all]
2025-09-30 07:30:42.243235 | 
2025-09-30 07:30:42.243399 | TASK [Abort when test_command variable is undefined]
2025-09-30 07:30:42.268549 | controller | skipping: Conditional result was False
2025-09-30 07:30:42.274765 | 
2025-09-30 07:30:42.274860 | TASK [Convert test_command to list]
2025-09-30 07:30:42.308965 | controller | skipping: Conditional result was False
2025-09-30 07:30:42.315680 | 
2025-09-30 07:30:42.315782 | TASK [Use test_command list]
2025-09-30 07:30:42.374521 | controller | ok
2025-09-30 07:30:42.380276 | 
2025-09-30 07:30:42.380390 | LOOP [Run test_command]
2025-09-30 07:30:42.790196 | controller | no check to run
2025-09-30 07:30:42.791208 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.009465
2025-09-30 07:30:42.837835 | 
2025-09-30 07:30:42.837952 | PLAY RECAP
2025-09-30 07:30:42.838019 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-30 07:30:42.838055 | 
2025-09-30 07:30:42.937374 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-09-30 07:30:42.938234 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 07:30:43.685080 | 
2025-09-30 07:30:43.685372 | PLAY [all]
2025-09-30 07:30:43.716364 | 
2025-09-30 07:30:43.716604 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-30 07:30:44.148186 | controller | changed: non-zero return code
2025-09-30 07:30:44.156539 | 
2025-09-30 07:30:44.156763 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-30 07:30:44.183480 | controller | skipping: Conditional result was False
2025-09-30 07:30:44.191200 | 
2025-09-30 07:30:44.191381 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-30 07:30:44.237051 | 
2025-09-30 07:30:44.237324 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-30 07:30:44.272582 | 
2025-09-30 07:30:44.272877 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-30 07:30:44.289896 | controller | skipping: Conditional result was False
2025-09-30 07:30:44.297928 | 
2025-09-30 07:30:44.298109 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-30 07:30:44.333160 | 
2025-09-30 07:30:44.333416 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-30 07:30:44.349152 | controller | skipping: Conditional result was False
2025-09-30 07:30:44.357381 | 
2025-09-30 07:30:44.357585 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-30 07:30:44.373622 | controller | skipping: Conditional result was False
2025-09-30 07:30:44.384548 | 
2025-09-30 07:30:44.384826 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-30 07:30:44.413091 | controller | skipping: Conditional result was False
2025-09-30 07:30:44.447818 | 
2025-09-30 07:30:44.448000 | PLAY RECAP
2025-09-30 07:30:44.448061 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-30 07:30:44.448106 | 
2025-09-30 07:30:44.656330 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 07:30:44.657635 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 07:30:45.432715 | 
2025-09-30 07:30:45.432967 | PLAY [all]
2025-09-30 07:30:45.455554 | 
2025-09-30 07:30:45.455773 | TASK [include_role : fetch-output]
2025-09-30 07:30:45.497784 | controller | ok
2025-09-30 07:30:45.517337 | 
2025-09-30 07:30:45.517556 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-30 07:30:45.575313 | controller | skipping: Conditional result was False
2025-09-30 07:30:45.582759 | 
2025-09-30 07:30:45.582902 | TASK [fetch-output : Set log path for single node]
2025-09-30 07:30:45.650761 | controller | ok
2025-09-30 07:30:45.658856 | 
2025-09-30 07:30:45.658998 | LOOP [fetch-output : Ensure local output dirs]
2025-09-30 07:30:46.129966 | controller -> localhost | ok: "/var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/work/logs"
2025-09-30 07:30:46.421378 | controller -> localhost | changed: "/var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/work/artifacts"
2025-09-30 07:30:46.682767 | controller -> localhost | changed: "/var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/work/docs"
2025-09-30 07:30:46.701595 | 
2025-09-30 07:30:46.701910 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-30 07:30:47.461903 | controller | changed: .d..t...... ./
2025-09-30 07:30:47.462344 | controller | changed: All items complete
2025-09-30 07:30:47.462403 | 
2025-09-30 07:30:47.950471 | controller | changed: .d..t...... ./
2025-09-30 07:30:48.421215 | controller | changed: .d..t...... ./
2025-09-30 07:30:48.456821 | 
2025-09-30 07:30:48.456975 | TASK [include_role : fetch-output-openshift]
2025-09-30 07:30:48.484038 | controller | skipping: Conditional result was False
2025-09-30 07:30:48.496605 | 
2025-09-30 07:30:48.496815 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-30 07:30:49.032110 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.012380
2025-09-30 07:30:49.290070 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.009713
2025-09-30 07:30:49.326371 | 
2025-09-30 07:30:49.326474 | PLAY [all]
2025-09-30 07:30:49.341968 | 
2025-09-30 07:30:49.342086 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-09-30 07:30:49.826433 | controller | changed
2025-09-30 07:30:49.871595 | 
2025-09-30 07:30:49.871745 | PLAY RECAP
2025-09-30 07:30:49.871808 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-30 07:30:49.871839 | 
2025-09-30 07:30:49.980964 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 07:30:49.982811 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-09-30 07:30:50.648958 | 
2025-09-30 07:30:50.649082 | PLAY [localhost]
2025-09-30 07:30:50.667760 | 
2025-09-30 07:30:50.667895 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-30 07:30:51.063352 | localhost | changed
2025-09-30 07:30:51.068183 | 
2025-09-30 07:30:51.068266 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-30 07:30:51.108463 | localhost | ok
2025-09-30 07:30:51.117013 | 
2025-09-30 07:30:51.117111 | TASK [add-fileserver : Create SSH private key tempfile]
2025-09-30 07:30:51.501706 | localhost | changed
2025-09-30 07:30:51.519208 | 
2025-09-30 07:30:51.519423 | TASK [add-fileserver : Create SSH private key from secret]
2025-09-30 07:30:52.255335 | localhost | changed
2025-09-30 07:30:52.270994 | 
2025-09-30 07:30:52.271172 | TASK [add-fileserver : Add fileserver ssh key]
2025-09-30 07:30:52.734923 | localhost | Identity added: /var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/work/tmp/ansible.t5aeslyv (/var/lib/zuul/builds/37c64e4c23984c58a3a801c8fde8fd2a/work/tmp/ansible.t5aeslyv)
2025-09-30 07:30:52.735280 | localhost | ok: Runtime: 0:00:00.013139
2025-09-30 07:30:52.746194 | 
2025-09-30 07:30:52.746343 | TASK [add-fileserver : Remove SSH private key from disk]
2025-09-30 07:30:53.041307 | localhost | ok: Runtime: 0:00:00.005341
2025-09-30 07:30:53.052432 | 
2025-09-30 07:30:53.052571 | TASK [add-fileserver : Add fileserver to inventory]
2025-09-30 07:30:53.111925 | localhost | changed
2025-09-30 07:30:53.119402 | 
2025-09-30 07:30:53.119515 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-09-30 07:30:53.513773 | localhost | changed
2025-09-30 07:30:53.555802 | 
2025-09-30 07:30:53.555948 | PLAY [localhost]
2025-09-30 07:30:53.574128 | 
2025-09-30 07:30:53.574217 | TASK [Generate bulk log download script]
2025-09-30 07:30:53.595509 | localhost | ok
2025-09-30 07:30:53.612908 | 
2025-09-30 07:30:53.613013 | TASK [local-log-download : Check API endpoint is defined]
2025-09-30 07:30:53.655491 | localhost | ok: All assertions passed
2025-09-30 07:30:53.662641 | 
2025-09-30 07:30:53.662742 | TASK [local-log-download : Create download script]
2025-09-30 07:30:54.206094 | localhost -> localhost | changed
2025-09-30 07:30:54.216677 | 
2025-09-30 07:30:54.216776 | TASK [Register quick-download link]
2025-09-30 07:30:54.235530 | localhost | ok
2025-09-30 07:30:54.280199 | 
2025-09-30 07:30:54.280297 | PLAY [logserver.rdoproject.org]
2025-09-30 07:30:54.290556 | 
2025-09-30 07:30:54.290635 | TASK [Set zuul-log-path fact]
2025-09-30 07:30:54.307256 | logserver.rdoproject.org | ok
2025-09-30 07:30:54.317292 | 
2025-09-30 07:30:54.317412 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 07:30:54.344639 | logserver.rdoproject.org | ok
2025-09-30 07:30:54.350234 | 
2025-09-30 07:30:54.350327 | TASK [upload-logs : Create log directories]
2025-09-30 07:30:55.128024 | logserver.rdoproject.org | changed
2025-09-30 07:30:55.134834 | 
2025-09-30 07:30:55.134974 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-09-30 07:30:55.472483 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.005853
2025-09-30 07:30:55.483666 | 
2025-09-30 07:30:55.483876 | TASK [upload-logs : Upload logs to log server]
2025-09-30 07:30:56.317228 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-09-30 07:30:56.323993 | 
2025-09-30 07:30:56.324127 | LOOP [upload-logs : Compress console log and json output]
2025-09-30 07:30:56.390535 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 07:30:56.402911 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 07:30:56.416209 | 
2025-09-30 07:30:56.416287 | LOOP [upload-logs : Upload compressed console log and json output]
2025-09-30 07:30:56.460365 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 07:30:56.460634 | 
2025-09-30 07:30:56.463951 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 07:30:56.475752 | 
2025-09-30 07:30:56.475882 | LOOP [upload-logs : Upload console log and json output]