2025-10-02 19:26:59.154831 | Job console starting...
2025-10-02 19:26:59.170001 | Updating repositories
2025-10-02 19:26:59.202941 | Preparing job workspace
2025-10-02 19:27:02.778838 | Running Ansible setup...
2025-10-02 19:27:06.800743 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-02 19:27:07.363520 | 
2025-10-02 19:27:07.363627 | PLAY [localhost]
2025-10-02 19:27:07.372022 | 
2025-10-02 19:27:07.372089 | TASK [Gathering Facts]
2025-10-02 19:27:08.289051 | localhost | ok
2025-10-02 19:27:08.319216 | 
2025-10-02 19:27:08.319527 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-02 19:27:08.780523 | localhost -> localhost | changed
2025-10-02 19:27:08.786992 | 
2025-10-02 19:27:08.787064 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-02 19:27:09.583766 | localhost -> localhost | changed
2025-10-02 19:27:09.592082 | 
2025-10-02 19:27:09.592151 | TASK [Setup log path fact]
2025-10-02 19:27:09.614147 | localhost | ok
2025-10-02 19:27:09.629269 | 
2025-10-02 19:27:09.629348 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-02 19:27:09.657163 | localhost | ok
2025-10-02 19:27:09.664711 | 
2025-10-02 19:27:09.664775 | TASK [emit-job-header : Print job information]
2025-10-02 19:27:09.702756 | # Job Information
2025-10-02 19:27:09.702915 | Ansible Version: 2.15.12
2025-10-02 19:27:09.702942 | Job: cifmw-molecule-ipa
2025-10-02 19:27:09.702962 | Pipeline: github-check
2025-10-02 19:27:09.702980 | Executor: ze02.softwarefactory-project.io
2025-10-02 19:27:09.702998 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3362
2025-10-02 19:27:09.703017 | Log URL (when completed): https://logserver.rdoproject.org/799/rdoproject.org/799effac0d984bf79144a3d1b5569488/
2025-10-02 19:27:09.703035 | Event ID: 9ca491d0-9fc5-11f0-8734-f8eb35e200a5
2025-10-02 19:27:09.707020 | 
2025-10-02 19:27:09.707082 | LOOP [emit-job-header : Print node information]
2025-10-02 19:27:09.797127 | localhost | ok:
2025-10-02 19:27:09.797318 | localhost | # Node Information
2025-10-02 19:27:09.797353 | localhost | Inventory Hostname: controller
2025-10-02 19:27:09.797381 | localhost | Hostname: np0005467142
2025-10-02 19:27:09.797401 | localhost | Username: zuul
2025-10-02 19:27:09.797423 | localhost | Distro: CentOS 9
2025-10-02 19:27:09.797445 | localhost | Provider: vexxhost-nodepool-tripleo
2025-10-02 19:27:09.797463 | localhost | Region: RegionOne
2025-10-02 19:27:09.797480 | localhost | Label: cloud-centos-9-stream-tripleo
2025-10-02 19:27:09.797496 | localhost | Product Name: OpenStack Nova
2025-10-02 19:27:09.797511 | localhost | Interface IP: 38.102.83.159
2025-10-02 19:27:09.821906 | 
2025-10-02 19:27:09.822001 | PLAY [all]
2025-10-02 19:27:09.828138 | 
2025-10-02 19:27:09.828212 | TASK [Gather network facts]
2025-10-02 19:27:10.338264 | controller | ok
2025-10-02 19:27:10.356399 | 
2025-10-02 19:27:10.356485 | TASK [include_role : start-zuul-console]
2025-10-02 19:27:10.374386 | controller | ok
2025-10-02 19:27:10.387988 | 
2025-10-02 19:27:10.388049 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-02 19:27:10.841840 | controller | ok
2025-10-02 19:27:10.853893 | 
2025-10-02 19:27:10.854021 | TASK [include_role : add-build-sshkey]
2025-10-02 19:27:10.895573 | controller | ok
2025-10-02 19:27:10.913703 | 
2025-10-02 19:27:10.913842 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-02 19:27:11.180293 | controller -> localhost | ok
2025-10-02 19:27:11.194739 | 
2025-10-02 19:27:11.194873 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-02 19:27:11.218237 | controller | ok
2025-10-02 19:27:11.235616 | controller | included: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-02 19:27:11.243596 | 
2025-10-02 19:27:11.243704 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-02 19:27:11.912116 | controller -> localhost | Generating public/private rsa key pair.
2025-10-02 19:27:11.912304 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/work/799effac0d984bf79144a3d1b5569488_id_rsa.
2025-10-02 19:27:11.912335 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/work/799effac0d984bf79144a3d1b5569488_id_rsa.pub.
2025-10-02 19:27:11.912357 | controller -> localhost | The key fingerprint is:
2025-10-02 19:27:11.912376 | controller -> localhost | SHA256:8gMCRl5/ccwHVZofRWV/G5GFeJ7Nn84Nqnud6dWxo+Y zuul-build-sshkey
2025-10-02 19:27:11.912395 | controller -> localhost | The key's randomart image is:
2025-10-02 19:27:11.912413 | controller -> localhost | +---[RSA 3072]----+
2025-10-02 19:27:11.912431 | controller -> localhost | |  . .   .ooo.o.+X|
2025-10-02 19:27:11.912448 | controller -> localhost | | o . .   oo ooo+o|
2025-10-02 19:27:11.912466 | controller -> localhost | |  +   . .  .oo.=o|
2025-10-02 19:27:11.912484 | controller -> localhost | | . .   .     .o.*|
2025-10-02 19:27:11.912502 | controller -> localhost | |    . o S     .oo|
2025-10-02 19:27:11.912519 | controller -> localhost | |     . +      ..=|
2025-10-02 19:27:11.912536 | controller -> localhost | |        o    oo*+|
2025-10-02 19:27:11.912556 | controller -> localhost | |         .  o.=+o|
2025-10-02 19:27:11.912574 | controller -> localhost | |          o+oE.  |
2025-10-02 19:27:11.912591 | controller -> localhost | +----[SHA256]-----+
2025-10-02 19:27:11.912630 | controller -> localhost | ok: Runtime: 0:00:00.285875
2025-10-02 19:27:11.918703 | 
2025-10-02 19:27:11.918763 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-02 19:27:11.939274 | controller | ok
2025-10-02 19:27:11.948861 | controller | included: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-02 19:27:11.956758 | 
2025-10-02 19:27:11.956816 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-02 19:27:11.970386 | controller | skipping: Conditional result was False
2025-10-02 19:27:11.975798 | 
2025-10-02 19:27:11.975858 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-02 19:27:12.442646 | controller | changed
2025-10-02 19:27:12.457475 | 
2025-10-02 19:27:12.457561 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-02 19:27:12.732800 | controller | ok
2025-10-02 19:27:12.738071 | 
2025-10-02 19:27:12.738140 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-02 19:27:13.604020 | controller | changed
2025-10-02 19:27:13.614884 | 
2025-10-02 19:27:13.615017 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-02 19:27:14.513320 | controller | changed
2025-10-02 19:27:14.521827 | 
2025-10-02 19:27:14.521913 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-02 19:27:14.557473 | controller | skipping: Conditional result was False
2025-10-02 19:27:14.564835 | 
2025-10-02 19:27:14.564920 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-02 19:27:14.926081 | controller -> localhost | changed
2025-10-02 19:27:14.935573 | 
2025-10-02 19:27:14.935636 | TASK [add-build-sshkey : Add back temp key]
2025-10-02 19:27:15.204745 | controller -> localhost | Identity added: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/work/799effac0d984bf79144a3d1b5569488_id_rsa (zuul-build-sshkey)
2025-10-02 19:27:15.205088 | controller -> localhost | ok: Runtime: 0:00:00.019224
2025-10-02 19:27:15.219047 | 
2025-10-02 19:27:15.219128 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-02 19:27:15.664876 | controller | ok
2025-10-02 19:27:15.672631 | 
2025-10-02 19:27:15.672717 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-02 19:27:15.697324 | controller | skipping: Conditional result was False
2025-10-02 19:27:15.710317 | 
2025-10-02 19:27:15.710380 | TASK [include_role : validate-host]
2025-10-02 19:27:15.738182 | controller | ok
2025-10-02 19:27:15.761094 | 
2025-10-02 19:27:15.761183 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-02 19:27:15.791034 | controller | ok
2025-10-02 19:27:15.808613 | 
2025-10-02 19:27:15.808705 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-02 19:27:16.085294 | controller -> localhost | ok
2025-10-02 19:27:16.091099 | 
2025-10-02 19:27:16.091172 | TASK [validate-host : Collect information about the host]
2025-10-02 19:27:17.011495 | controller | ok
2025-10-02 19:27:17.026622 | 
2025-10-02 19:27:17.026762 | TASK [validate-host : Sanitize hostname]
2025-10-02 19:27:17.086859 | controller | ok
2025-10-02 19:27:17.091899 | 
2025-10-02 19:27:17.091961 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-02 19:27:17.638591 | controller -> localhost | changed
2025-10-02 19:27:17.644158 | 
2025-10-02 19:27:17.644229 | TASK [validate-host : Collect information about zuul worker]
2025-10-02 19:27:19.221815 | controller | ok
2025-10-02 19:27:19.227036 | 
2025-10-02 19:27:19.227108 | TASK [validate-host : Write out all zuul information for each host]
2025-10-02 19:27:19.736649 | controller -> localhost | changed
2025-10-02 19:27:19.747051 | 
2025-10-02 19:27:19.747142 | TASK [include_role : prepare-workspace-openshift]
2025-10-02 19:27:19.760435 | controller | skipping: Conditional result was False
2025-10-02 19:27:19.766269 | 
2025-10-02 19:27:19.766344 | TASK [include_role : remove-zuul-sshkey]
2025-10-02 19:27:19.794683 | controller | skipping: Conditional result was False
2025-10-02 19:27:19.799710 | 
2025-10-02 19:27:19.799775 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-02 19:27:20.093564 | controller | ok: "logs"
2025-10-02 19:27:20.093798 | controller | ok: All items complete
2025-10-02 19:27:20.093826 | 
2025-10-02 19:27:20.314809 | controller | ok: "artifacts"
2025-10-02 19:27:20.535028 | controller | ok: "docs"
2025-10-02 19:27:20.547013 | 
2025-10-02 19:27:20.547152 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-02 19:27:20.849453 | controller | changed: "logs"
2025-10-02 19:27:21.099657 | controller | changed: "artifacts"
2025-10-02 19:27:21.369066 | controller | changed: "docs"
2025-10-02 19:27:21.421205 | 
2025-10-02 19:27:21.421303 | PLAY RECAP
2025-10-02 19:27:21.421346 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-02 19:27:21.421371 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-02 19:27:21.421388 | 
2025-10-02 19:27:21.531620 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-02 19:27:21.532644 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-02 19:27:22.131740 | 
2025-10-02 19:27:22.131850 | PLAY [localhost]
2025-10-02 19:27:22.147925 | 
2025-10-02 19:27:22.147998 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-10-02 19:27:22.534038 | localhost | ok
2025-10-02 19:27:22.539204 | 
2025-10-02 19:27:22.539277 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-10-02 19:27:23.261386 | localhost | changed
2025-10-02 19:27:23.281302 | 
2025-10-02 19:27:23.281356 | PLAY [all]
2025-10-02 19:27:23.296368 | 
2025-10-02 19:27:23.296429 | TASK [include_role : prepare-workspace]
2025-10-02 19:27:23.325176 | controller | ok
2025-10-02 19:27:23.341581 | 
2025-10-02 19:27:23.341649 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-02 19:27:23.814325 | controller | ok
2025-10-02 19:27:23.821257 | 
2025-10-02 19:27:23.821324 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-02 19:27:25.629718 | controller | Output suppressed because no_log was given
2025-10-02 19:27:25.640079 | 
2025-10-02 19:27:25.640140 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-02 19:27:25.895289 | controller | changed: "logs"
2025-10-02 19:27:26.148467 | controller | changed: "artifacts"
2025-10-02 19:27:26.395734 | controller | changed: "docs"
2025-10-02 19:27:26.413599 | 
2025-10-02 19:27:26.413691 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-02 19:27:26.685892 | controller | changed: "logs"
2025-10-02 19:27:26.686107 | controller | changed: All items complete
2025-10-02 19:27:26.686134 | 
2025-10-02 19:27:26.998884 | controller | changed: "artifacts"
2025-10-02 19:27:27.232723 | controller | changed: "docs"
2025-10-02 19:27:27.255868 | 
2025-10-02 19:27:27.255979 | TASK [Check if worker can sudo]
2025-10-02 19:27:28.297066 | controller | ok: Runtime: 0:00:00.107296
2025-10-02 19:27:28.302773 | 
2025-10-02 19:27:28.302908 | TASK [configure-mirrors : Gather needed facts]
2025-10-02 19:27:28.357177 | controller | skipping: Conditional result was False
2025-10-02 19:27:28.363085 | 
2025-10-02 19:27:28.363150 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-10-02 19:27:28.445143 | controller | ok
2025-10-02 19:27:28.453327 | controller | included: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-10-02 19:27:28.486760 | 
2025-10-02 19:27:28.486873 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-10-02 19:27:28.804444 | controller | ok
2025-10-02 19:27:28.813242 | 
2025-10-02 19:27:28.813308 | LOOP [configure-mirrors : Include OS-specific variables]
2025-10-02 19:27:28.869297 | controller | ok: "/var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-10-02 19:27:28.878242 | 
2025-10-02 19:27:28.878351 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-10-02 19:27:29.695094 | controller | changed
2025-10-02 19:27:29.705340 | 
2025-10-02 19:27:29.705401 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-10-02 19:27:29.768808 | controller | ok: "/var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-10-02 19:27:29.769066 | controller | ok: All items complete
2025-10-02 19:27:29.769097 | 
2025-10-02 19:27:29.823315 | controller | included: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-10-02 19:27:29.830954 | 
2025-10-02 19:27:29.831024 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-10-02 19:27:30.793380 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-10-02 19:27:31.670934 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-10-02 19:27:31.684822 | 
2025-10-02 19:27:31.684918 | TASK [configure-mirrors : Disable deltrarpm]
2025-10-02 19:27:32.227015 | controller | changed: section and option added
2025-10-02 19:27:32.260104 | 
2025-10-02 19:27:32.260188 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-10-02 19:27:33.092052 | controller | 29 files removed
2025-10-02 19:27:33.092462 | controller | ok: Item: dnf clean all Runtime: 0:00:00.444118
2025-10-02 19:27:33.092552 | controller | changed: All items complete
2025-10-02 19:27:33.092608 | 
2025-10-02 19:27:45.647982 | 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-02 19:27:45.648091 | controller | DNF version: 4.14.0
2025-10-02 19:27:45.648116 | controller | cachedir: /var/cache/dnf
2025-10-02 19:27:45.648135 | controller | Making cache files for all metadata files.
2025-10-02 19:27:45.648153 | controller | baseos: has expired and will be refreshed.
2025-10-02 19:27:45.648171 | controller | appstream: has expired and will be refreshed.
2025-10-02 19:27:45.648187 | controller | crb: has expired and will be refreshed.
2025-10-02 19:27:45.648214 | controller | extras-common: has expired and will be refreshed.
2025-10-02 19:27:45.648231 | controller | repo: downloading from remote: baseos
2025-10-02 19:27:45.648248 | controller | CentOS Stream 9 - BaseOS                         71 MB/s | 8.8 MB     00:00
2025-10-02 19:27:45.648264 | controller | baseos: using metadata from Tue 30 Sep 2025 01:12:56 PM EDT.
2025-10-02 19:27:45.648281 | controller | repo: downloading from remote: appstream
2025-10-02 19:27:45.648297 | controller | CentOS Stream 9 - AppStream                      15 MB/s |  25 MB     00:01
2025-10-02 19:27:45.648312 | controller | appstream: using metadata from Tue 30 Sep 2025 01:16:29 PM EDT.
2025-10-02 19:27:45.648328 | controller | repo: downloading from remote: crb
2025-10-02 19:27:45.648344 | controller | CentOS Stream 9 - CRB                            34 MB/s | 7.1 MB     00:00
2025-10-02 19:27:45.648360 | controller | crb: using metadata from Tue 30 Sep 2025 01:20:54 PM EDT.
2025-10-02 19:27:45.648376 | controller | repo: downloading from remote: extras-common
2025-10-02 19:27:45.648392 | controller | CentOS Stream 9 - Extras packages               104 kB/s |  20 kB     00:00
2025-10-02 19:27:45.648407 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT.
2025-10-02 19:27:45.648423 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-10-02 19:27:45.648439 | controller | Completion plugin: Generating completion cache...
2025-10-02 19:27:45.648455 | controller | Metadata cache created.
2025-10-02 19:27:45.648479 | controller | ok: Item: dnf makecache -v Runtime: 0:00:12.228554
2025-10-02 19:27:45.707568 | 
2025-10-02 19:27:45.707721 | PLAY RECAP
2025-10-02 19:27:45.707780 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-02 19:27:45.707817 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-02 19:27:45.707843 | 
2025-10-02 19:27:45.824179 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-02 19:27:45.824979 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-02 19:27:46.422432 | 
2025-10-02 19:27:46.422535 | PLAY [all]
2025-10-02 19:27:46.444852 | 
2025-10-02 19:27:46.444937 | TASK [Install binary dependencies]
2025-10-02 19:27:46.524932 | controller | ok
2025-10-02 19:27:46.545083 | 
2025-10-02 19:27:46.545169 | TASK [bindep : Include find tasks]
2025-10-02 19:27:46.573419 | controller | ok
2025-10-02 19:27:46.580953 | controller | included: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-02 19:27:46.586804 | 
2025-10-02 19:27:46.586866 | TASK [bindep : Look for bindep.txt]
2025-10-02 19:27:46.971092 | controller | ok
2025-10-02 19:27:46.978251 | 
2025-10-02 19:27:46.978335 | TASK [bindep : Define bindep_file fact]
2025-10-02 19:27:47.020164 | controller | ok
2025-10-02 19:27:47.025257 | 
2025-10-02 19:27:47.025325 | TASK [bindep : Look for other-requirements.txt]
2025-10-02 19:27:47.049216 | controller | skipping: Conditional result was False
2025-10-02 19:27:47.055862 | 
2025-10-02 19:27:47.055954 | TASK [bindep : Define bindep_file fact]
2025-10-02 19:27:47.090236 | controller | skipping: Conditional result was False
2025-10-02 19:27:47.096110 | 
2025-10-02 19:27:47.096187 | TASK [bindep : Look for bindep fallback file]
2025-10-02 19:27:47.130490 | controller | skipping: Conditional result was False
2025-10-02 19:27:47.136419 | 
2025-10-02 19:27:47.136483 | TASK [bindep : Define bindep_file fact]
2025-10-02 19:27:47.170652 | controller | skipping: Conditional result was False
2025-10-02 19:27:47.176196 | 
2025-10-02 19:27:47.176256 | TASK [bindep : Include bindep tasks]
2025-10-02 19:27:47.222179 | controller | ok
2025-10-02 19:27:47.237191 | controller | included: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-10-02 19:27:47.249105 | 
2025-10-02 19:27:47.249187 | TASK [bindep : Look for bindep command]
2025-10-02 19:27:47.284750 | controller | skipping: Conditional result was False
2025-10-02 19:27:47.298814 | 
2025-10-02 19:27:47.298975 | TASK [bindep : Check for system bindep]
2025-10-02 19:27:47.838513 | controller | ok: Runtime: 0:00:00.005669
2025-10-02 19:27:47.843786 | 
2025-10-02 19:27:47.843848 | TASK [bindep : Define bindep_command fact]
2025-10-02 19:27:47.867469 | controller | skipping: Conditional result was False
2025-10-02 19:27:47.873006 | 
2025-10-02 19:27:47.873068 | TASK [bindep : Include install tasks]
2025-10-02 19:27:47.901609 | controller | ok
2025-10-02 19:27:47.909510 | controller | included: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-10-02 19:27:47.918192 | 
2025-10-02 19:27:47.918251 | TASK [bindep : Create temp dir for bindep]
2025-10-02 19:27:48.330947 | controller | changed
2025-10-02 19:27:48.336091 | 
2025-10-02 19:27:48.336147 | TASK [Ensure we have pip dependencies]
2025-10-02 19:27:48.354515 | controller | ok
2025-10-02 19:27:48.377440 | 
2025-10-02 19:27:48.377505 | TASK [ensure-pip : Check if pip is installed]
2025-10-02 15:27:48.677109 | controller | /usr/bin/pip3
2025-10-02 15:27:48.699193 | controller | /usr/bin/python3: No module named wheel
2025-10-02 19:27:48.905204 | controller | ok: Runtime: 0:00:00.033795
2025-10-02 19:27:48.910698 | 
2025-10-02 19:27:48.910761 | LOOP [ensure-pip : Install pip from packages]
2025-10-02 19:27:48.957895 | controller | ok: "/var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-10-02 19:27:48.975016 | controller | included: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-10-02 19:27:48.997140 | 
2025-10-02 19:27:48.997275 | TASK [ensure-pip : Install Python 3 pip]
2025-10-02 19:27:51.758067 | controller | changed
2025-10-02 19:27:51.763544 | 
2025-10-02 19:27:51.763606 | TASK [ensure-pip : Check for EPEL repository]
2025-10-02 19:27:51.834080 | controller | skipping: Conditional result was False
2025-10-02 19:27:51.841297 | 
2025-10-02 19:27:51.841381 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-10-02 19:27:51.898048 | controller | skipping: Conditional result was False
2025-10-02 19:27:51.907906 | 
2025-10-02 19:27:51.907995 | TASK [ensure-pip : Install Python 2 pip]
2025-10-02 19:27:51.953475 | controller | skipping: Conditional result was False
2025-10-02 19:27:51.962393 | 
2025-10-02 19:27:51.962491 | TASK [ensure-pip : Ensure setuptools]
2025-10-02 19:27:51.977737 | controller | skipping: Conditional result was False
2025-10-02 19:27:51.986324 | 
2025-10-02 19:27:51.986427 | TASK [ensure-pip : Check for ensurepip module]
2025-10-02 19:27:52.526063 | controller | skipping: Conditional result was False
2025-10-02 19:27:52.539087 | 
2025-10-02 19:27:52.539234 | TASK [ensure-pip : Ensure python3-venv]
2025-10-02 19:27:52.555883 | controller | skipping: Conditional result was False
2025-10-02 19:27:52.568927 | 
2025-10-02 19:27:52.569090 | TASK [ensure-pip : Install pip from source]
2025-10-02 19:27:52.596062 | controller | skipping: Conditional result was False
2025-10-02 19:27:52.623409 | 
2025-10-02 19:27:52.623567 | TASK [ensure-pip : Probe for venv python full path]
2025-10-02 15:27:52.906307 | controller | /usr/bin/python3
2025-10-02 19:27:53.166460 | controller | ok: Runtime: 0:00:00.009056
2025-10-02 19:27:53.171791 | 
2025-10-02 19:27:53.171948 | TASK [ensure-pip : Set host default]
2025-10-02 19:27:53.241375 | controller | ok
2025-10-02 19:27:53.246511 | 
2025-10-02 19:27:53.246573 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-10-02 19:27:53.309709 | controller | ok
2025-10-02 19:27:53.320194 | 
2025-10-02 19:27:53.320253 | TASK [bindep : Install bindep into temporary venv]
2025-10-02 19:27:57.941920 | controller | changed
2025-10-02 19:27:57.958737 | 
2025-10-02 19:27:57.958897 | TASK [bindep : Define bindep_command]
2025-10-02 19:27:57.998816 | controller | ok
2025-10-02 19:27:58.010255 | 
2025-10-02 19:27:58.010390 | LOOP [bindep : Include package tasks]
2025-10-02 19:27:58.104489 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-10-02 19:27:58.104716 | controller | ok: All items complete
2025-10-02 19:27:58.104754 | 
2025-10-02 19:27:58.125836 | controller | included: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-10-02 19:27:58.141869 | 
2025-10-02 19:27:58.141952 | TASK [bindep : Define bindep_run fact]
2025-10-02 19:27:58.181912 | controller | ok
2025-10-02 19:27:58.189954 | 
2025-10-02 19:27:58.190041 | TASK [bindep : Get list of packages to install from bindep]
2025-10-02 15:27:59.639100 | controller | podman
2025-10-02 15:27:59.694967 | controller | python3-jmespath
2025-10-02 15:27:59.695034 | controller | python3-libvirt
2025-10-02 15:27:59.695042 | controller | python3-lxml
2025-10-02 15:27:59.695051 | controller | python3-netaddr
2025-10-02 19:27:59.745186 | controller | ok: Runtime: 0:00:01.236616
2025-10-02 19:27:59.756723 | 
2025-10-02 19:27:59.756815 | TASK [bindep : Install distro packages from bindep]
2025-10-02 19:29:18.115023 | controller | changed
2025-10-02 19:29:18.120799 | 
2025-10-02 19:29:18.120864 | TASK [bindep : Check that packages are installed]
2025-10-02 19:29:19.663127 | controller | ok: Runtime: 0:00:01.088367
2025-10-02 19:29:19.668878 | 
2025-10-02 19:29:19.668940 | TASK [bindep : Fail if we cannot install all packages]
2025-10-02 19:29:19.702989 | controller | skipping: Conditional result was False
2025-10-02 19:29:19.713479 | 
2025-10-02 19:29:19.713544 | TASK [Run test-setup role]
2025-10-02 19:29:19.755120 | controller | ok
2025-10-02 19:29:19.782050 | 
2025-10-02 19:29:19.782127 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-02 19:29:20.023570 | controller | ok
2025-10-02 19:29:20.028921 | 
2025-10-02 19:29:20.028985 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-02 19:29:20.582179 | controller | skipping: Conditional result was False
2025-10-02 19:29:20.601425 | 
2025-10-02 19:29:20.601496 | TASK [bindep : Remove bindep temp dir]
2025-10-02 19:29:20.990521 | controller | ok
2025-10-02 19:29:21.001652 | 
2025-10-02 19:29:21.001732 | PLAY RECAP
2025-10-02 19:29:21.001774 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-10-02 19:29:21.001795 | 
2025-10-02 19:29:21.095345 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-02 19:29:21.096178 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-02 19:29:21.666189 | 
2025-10-02 19:29:21.666299 | PLAY [all]
2025-10-02 19:29:21.699752 | 
2025-10-02 19:29:21.699853 | TASK [Abort when test_command variable is undefined]
2025-10-02 19:29:21.734582 | controller | skipping: Conditional result was False
2025-10-02 19:29:21.740705 | 
2025-10-02 19:29:21.740786 | TASK [Convert test_command to list]
2025-10-02 19:29:21.776622 | controller | skipping: Conditional result was False
2025-10-02 19:29:21.783358 | 
2025-10-02 19:29:21.783440 | TASK [Use test_command list]
2025-10-02 19:29:21.845148 | controller | ok
2025-10-02 19:29:21.853207 | 
2025-10-02 19:29:21.853336 | LOOP [Run test_command]
2025-10-02 19:29:22.284784 | controller | no check to run
2025-10-02 19:29:22.285040 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.005838
2025-10-02 19:29:22.311799 | 
2025-10-02 19:29:22.311869 | PLAY RECAP
2025-10-02 19:29:22.311911 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-02 19:29:22.311931 | 
2025-10-02 19:29:22.409953 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-02 19:29:22.410793 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-02 19:29:23.000248 | 
2025-10-02 19:29:23.000351 | PLAY [all]
2025-10-02 19:29:23.033274 | 
2025-10-02 19:29:23.033368 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-02 19:29:23.369191 | controller | changed: non-zero return code
2025-10-02 19:29:23.376793 | 
2025-10-02 19:29:23.376894 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-02 19:29:23.392296 | controller | skipping: Conditional result was False
2025-10-02 19:29:23.400787 | 
2025-10-02 19:29:23.400900 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-02 19:29:23.462223 | 
2025-10-02 19:29:23.462392 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-02 19:29:23.495251 | 
2025-10-02 19:29:23.495436 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-02 19:29:23.519496 | controller | skipping: Conditional result was False
2025-10-02 19:29:23.527619 | 
2025-10-02 19:29:23.527731 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-02 19:29:23.559636 | 
2025-10-02 19:29:23.559815 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-02 19:29:23.574603 | controller | skipping: Conditional result was False
2025-10-02 19:29:23.585237 | 
2025-10-02 19:29:23.585347 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-02 19:29:23.604301 | controller | skipping: Conditional result was False
2025-10-02 19:29:23.613002 | 
2025-10-02 19:29:23.613092 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-02 19:29:23.627511 | controller | skipping: Conditional result was False
2025-10-02 19:29:23.658608 | 
2025-10-02 19:29:23.658658 | PLAY RECAP
2025-10-02 19:29:23.658719 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-02 19:29:23.658739 | 
2025-10-02 19:29:23.750179 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-02 19:29:23.750985 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-02 19:29:24.332786 | 
2025-10-02 19:29:24.332895 | PLAY [all]
2025-10-02 19:29:24.352627 | 
2025-10-02 19:29:24.352715 | TASK [include_role : fetch-output]
2025-10-02 19:29:24.395946 | controller | ok
2025-10-02 19:29:24.412993 | 
2025-10-02 19:29:24.413070 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-02 19:29:24.456849 | controller | skipping: Conditional result was False
2025-10-02 19:29:24.462366 | 
2025-10-02 19:29:24.462434 | TASK [fetch-output : Set log path for single node]
2025-10-02 19:29:24.491167 | controller | ok
2025-10-02 19:29:24.496089 | 
2025-10-02 19:29:24.496166 | LOOP [fetch-output : Ensure local output dirs]
2025-10-02 19:29:24.911512 | controller -> localhost | ok: "/var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/work/logs"
2025-10-02 19:29:25.156933 | controller -> localhost | changed: "/var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/work/artifacts"
2025-10-02 19:29:25.420112 | controller -> localhost | changed: "/var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/work/docs"
2025-10-02 19:29:25.443388 | 
2025-10-02 19:29:25.443592 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-02 19:29:26.055967 | controller | changed: .d..t...... ./
2025-10-02 19:29:26.056205 | controller | changed: All items complete
2025-10-02 19:29:26.056235 | 
2025-10-02 19:29:26.555243 | controller | changed: .d..t...... ./
2025-10-02 19:29:27.056511 | controller | changed: .d..t...... ./
2025-10-02 19:29:27.069946 | 
2025-10-02 19:29:27.070011 | TASK [include_role : fetch-output-openshift]
2025-10-02 19:29:27.094107 | controller | skipping: Conditional result was False
2025-10-02 19:29:27.100350 | 
2025-10-02 19:29:27.100416 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-02 19:29:27.488081 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.012837
2025-10-02 19:29:27.701077 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.006864
2025-10-02 19:29:27.744007 | 
2025-10-02 19:29:27.744105 | PLAY [all]
2025-10-02 19:29:27.760861 | 
2025-10-02 19:29:27.761020 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-02 19:29:28.196946 | controller | changed
2025-10-02 19:29:28.231794 | 
2025-10-02 19:29:28.231899 | PLAY RECAP
2025-10-02 19:29:28.231940 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-02 19:29:28.231960 | 
2025-10-02 19:29:28.352247 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-02 19:29:28.353382 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-02 19:29:28.941143 | 
2025-10-02 19:29:28.941247 | PLAY [localhost]
2025-10-02 19:29:28.958628 | 
2025-10-02 19:29:28.958721 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-02 19:29:29.328120 | localhost | changed
2025-10-02 19:29:29.343420 | 
2025-10-02 19:29:29.343611 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-02 19:29:29.372237 | localhost | ok
2025-10-02 19:29:29.381797 | 
2025-10-02 19:29:29.381868 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-02 19:29:29.751204 | localhost | changed
2025-10-02 19:29:29.756203 | 
2025-10-02 19:29:29.756319 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-02 19:29:30.393613 | localhost | changed
2025-10-02 19:29:30.398577 | 
2025-10-02 19:29:30.398639 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-02 19:29:30.822926 | localhost | Identity added: /var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/work/tmp/ansible.am9tkf9u (/var/lib/zuul/builds/799effac0d984bf79144a3d1b5569488/work/tmp/ansible.am9tkf9u)
2025-10-02 19:29:30.823111 | localhost | ok: Runtime: 0:00:00.006901
2025-10-02 19:29:30.827555 | 
2025-10-02 19:29:30.827898 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-02 19:29:31.089587 | localhost | ok: Runtime: 0:00:00.008304
2025-10-02 19:29:31.094287 | 
2025-10-02 19:29:31.094348 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-02 19:29:31.142510 | localhost | changed
2025-10-02 19:29:31.147258 | 
2025-10-02 19:29:31.147338 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-02 19:29:31.601163 | localhost | changed
2025-10-02 19:29:31.620816 | 
2025-10-02 19:29:31.620870 | PLAY [localhost]
2025-10-02 19:29:31.632268 | 
2025-10-02 19:29:31.632325 | TASK [Generate bulk log download script]
2025-10-02 19:29:31.651844 | localhost | ok
2025-10-02 19:29:31.664042 | 
2025-10-02 19:29:31.664104 | TASK [local-log-download : Check API endpoint is defined]
2025-10-02 19:29:31.712153 | localhost | ok: All assertions passed
2025-10-02 19:29:31.716724 | 
2025-10-02 19:29:31.716795 | TASK [local-log-download : Create download script]
2025-10-02 19:29:32.156822 | localhost -> localhost | changed
2025-10-02 19:29:32.175821 | 
2025-10-02 19:29:32.175956 | TASK [Register quick-download link]
2025-10-02 19:29:32.201051 | localhost | ok
2025-10-02 19:29:32.262211 | 
2025-10-02 19:29:32.262321 | PLAY [logserver.rdoproject.org]
2025-10-02 19:29:32.272084 | 
2025-10-02 19:29:32.272141 | TASK [Set zuul-log-path fact]
2025-10-02 19:29:32.288383 | logserver.rdoproject.org | ok
2025-10-02 19:29:32.297485 | 
2025-10-02 19:29:32.297547 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-02 19:29:32.324064 | logserver.rdoproject.org | ok
2025-10-02 19:29:32.329272 | 
2025-10-02 19:29:32.329334 | TASK [upload-logs : Create log directories]
2025-10-02 19:29:33.002254 | logserver.rdoproject.org | changed
2025-10-02 19:29:33.009037 | 
2025-10-02 19:29:33.009170 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-02 19:29:33.322087 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.005209
2025-10-02 19:29:33.326809 | 
2025-10-02 19:29:33.326876 | TASK [upload-logs : Upload logs to log server]
2025-10-02 19:29:33.989387 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-02 19:29:33.993322 | 
2025-10-02 19:29:33.993412 | LOOP [upload-logs : Compress console log and json output]
2025-10-02 19:29:34.062116 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 19:29:34.070384 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 19:29:34.082725 | 
2025-10-02 19:29:34.082808 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-02 19:29:34.122443 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 19:29:34.122727 | 
2025-10-02 19:29:34.127342 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 19:29:34.139827 | 
2025-10-02 19:29:34.139902 | LOOP [upload-logs : Upload console log and json output]