2025-10-13 14:52:53.889831 | Job console starting...
2025-10-13 14:52:53.899684 | Updating repositories
2025-10-13 14:52:53.933622 | Preparing job workspace
2025-10-13 14:53:04.412767 | Running Ansible setup...
2025-10-13 14:53:10.726891 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-13 14:53:14.281250 | 
2025-10-13 14:53:14.281404 | PLAY [localhost]
2025-10-13 14:53:14.303417 | 
2025-10-13 14:53:14.303590 | TASK [Gathering Facts]
2025-10-13 14:53:15.812530 | localhost | ok
2025-10-13 14:53:15.836303 | 
2025-10-13 14:53:15.836467 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-13 14:53:16.623897 | localhost -> localhost | changed
2025-10-13 14:53:16.630495 | 
2025-10-13 14:53:16.630585 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-13 14:53:18.220925 | localhost -> localhost | changed
2025-10-13 14:53:18.229463 | 
2025-10-13 14:53:18.229551 | TASK [Setup log path fact]
2025-10-13 14:53:18.252247 | localhost | ok
2025-10-13 14:53:18.268090 | 
2025-10-13 14:53:18.268206 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 14:53:18.299008 | localhost | ok
2025-10-13 14:53:18.339762 | 
2025-10-13 14:53:18.339872 | TASK [emit-job-header : Print job information]
2025-10-13 14:53:18.378709 | # Job Information
2025-10-13 14:53:18.378891 | Ansible Version: 2.15.12
2025-10-13 14:53:18.378924 | Job: cifmw-molecule-cifmw_helpers
2025-10-13 14:53:18.378945 | Pipeline: github-check
2025-10-13 14:53:18.378963 | Executor: ze03.softwarefactory-project.io
2025-10-13 14:53:18.378981 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3402
2025-10-13 14:53:18.379000 | Log URL (when completed): https://logserver.rdoproject.org/b23/rdoproject.org/b23ac3699c634dcca43edf9504037a43/
2025-10-13 14:53:18.379018 | Event ID: 03ccc7c0-a844-11f0-9fcd-d5792746e07c
2025-10-13 14:53:18.384870 | 
2025-10-13 14:53:18.384956 | LOOP [emit-job-header : Print node information]
2025-10-13 14:53:18.592367 | localhost | ok:
2025-10-13 14:53:18.592600 | localhost | # Node Information
2025-10-13 14:53:18.592629 | localhost | Inventory Hostname: controller
2025-10-13 14:53:18.592653 | localhost | Hostname: np0005485321
2025-10-13 14:53:18.592674 | localhost | Username: zuul
2025-10-13 14:53:18.592696 | localhost | Distro: CentOS 9
2025-10-13 14:53:18.592715 | localhost | Provider: vexxhost-nodepool-tripleo
2025-10-13 14:53:18.592778 | localhost | Region: RegionOne
2025-10-13 14:53:18.592798 | localhost | Label: cloud-centos-9-stream-tripleo
2025-10-13 14:53:18.592816 | localhost | Product Name: OpenStack Nova
2025-10-13 14:53:18.592833 | localhost | Interface IP: 38.129.56.42
2025-10-13 14:53:18.635245 | 
2025-10-13 14:53:18.635353 | PLAY [all]
2025-10-13 14:53:18.646699 | 
2025-10-13 14:53:18.646822 | TASK [Gather network facts]
2025-10-13 14:53:19.118710 | controller | ok
2025-10-13 14:53:19.143632 | 
2025-10-13 14:53:19.143761 | TASK [include_role : start-zuul-console]
2025-10-13 14:53:19.173706 | controller | ok
2025-10-13 14:53:19.186789 | 
2025-10-13 14:53:19.187026 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-13 14:53:19.683505 | controller | ok
2025-10-13 14:53:19.722842 | 
2025-10-13 14:53:19.722961 | TASK [include_role : add-build-sshkey]
2025-10-13 14:53:19.785528 | controller | ok
2025-10-13 14:53:19.813035 | 
2025-10-13 14:53:19.813141 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-13 14:53:20.239010 | controller -> localhost | ok
2025-10-13 14:53:20.245590 | 
2025-10-13 14:53:20.245697 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-13 14:53:20.297441 | controller | ok
2025-10-13 14:53:20.332380 | controller | included: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-13 14:53:20.352618 | 
2025-10-13 14:53:20.352786 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-13 14:53:21.198237 | controller -> localhost | Generating public/private rsa key pair.
2025-10-13 14:53:21.198420 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/work/b23ac3699c634dcca43edf9504037a43_id_rsa.
2025-10-13 14:53:21.198453 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/work/b23ac3699c634dcca43edf9504037a43_id_rsa.pub.
2025-10-13 14:53:21.198476 | controller -> localhost | The key fingerprint is:
2025-10-13 14:53:21.198496 | controller -> localhost | SHA256:b/RrNjF2WqUjrCM5EBjLViWQMXtisTaGh1pBKw1VMv8 zuul-build-sshkey
2025-10-13 14:53:21.198515 | controller -> localhost | The key's randomart image is:
2025-10-13 14:53:21.198533 | controller -> localhost | +---[RSA 3072]----+
2025-10-13 14:53:21.198551 | controller -> localhost | |.o*.*+...        |
2025-10-13 14:53:21.198569 | controller -> localhost | | o Oo=..         |
2025-10-13 14:53:21.198586 | controller -> localhost | |. *.@=.          |
2025-10-13 14:53:21.198604 | controller -> localhost | | + ===.         .|
2025-10-13 14:53:21.198622 | controller -> localhost | |.  .  E.S ..   o |
2025-10-13 14:53:21.198639 | controller -> localhost | |      .  o .* =  |
2025-10-13 14:53:21.198656 | controller -> localhost | |       . .oo.B . |
2025-10-13 14:53:21.198673 | controller -> localhost | |        +.o =.   |
2025-10-13 14:53:21.198689 | controller -> localhost | |         o +..   |
2025-10-13 14:53:21.198706 | controller -> localhost | +----[SHA256]-----+
2025-10-13 14:53:21.198774 | controller -> localhost | ok: Runtime: 0:00:00.230261
2025-10-13 14:53:21.205718 | 
2025-10-13 14:53:21.205807 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-13 14:53:21.235317 | controller | ok
2025-10-13 14:53:21.246550 | controller | included: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-13 14:53:21.256319 | 
2025-10-13 14:53:21.256417 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-13 14:53:21.271662 | controller | skipping: Conditional result was False
2025-10-13 14:53:21.277472 | 
2025-10-13 14:53:21.277623 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-13 14:53:21.754850 | controller | changed
2025-10-13 14:53:21.769756 | 
2025-10-13 14:53:21.769937 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-13 14:53:22.031848 | controller | ok
2025-10-13 14:53:22.042788 | 
2025-10-13 14:53:22.042941 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-13 14:53:22.821880 | controller | changed
2025-10-13 14:53:22.837241 | 
2025-10-13 14:53:22.837350 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-13 14:53:23.694838 | controller | changed
2025-10-13 14:53:23.711790 | 
2025-10-13 14:53:23.711916 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-13 14:53:23.748049 | controller | skipping: Conditional result was False
2025-10-13 14:53:23.754217 | 
2025-10-13 14:53:23.754339 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-13 14:53:24.268283 | controller -> localhost | changed
2025-10-13 14:53:24.279050 | 
2025-10-13 14:53:24.279160 | TASK [add-build-sshkey : Add back temp key]
2025-10-13 14:53:24.547788 | controller -> localhost | Identity added: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/work/b23ac3699c634dcca43edf9504037a43_id_rsa (zuul-build-sshkey)
2025-10-13 14:53:24.548014 | controller -> localhost | ok: Runtime: 0:00:00.009248
2025-10-13 14:53:24.553806 | 
2025-10-13 14:53:24.553909 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-13 14:53:24.983209 | controller | ok
2025-10-13 14:53:24.988268 | 
2025-10-13 14:53:24.988364 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-13 14:53:25.012847 | controller | skipping: Conditional result was False
2025-10-13 14:53:25.027051 | 
2025-10-13 14:53:25.027163 | TASK [include_role : validate-host]
2025-10-13 14:53:25.052998 | controller | ok
2025-10-13 14:53:25.104647 | 
2025-10-13 14:53:25.104772 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-13 14:53:25.133101 | controller | ok
2025-10-13 14:53:25.137836 | 
2025-10-13 14:53:25.138010 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-13 14:53:25.404474 | controller -> localhost | ok
2025-10-13 14:53:25.410557 | 
2025-10-13 14:53:25.410635 | TASK [validate-host : Collect information about the host]
2025-10-13 14:53:26.160619 | controller | ok
2025-10-13 14:53:26.175431 | 
2025-10-13 14:53:26.175567 | TASK [validate-host : Sanitize hostname]
2025-10-13 14:53:26.226420 | controller | ok
2025-10-13 14:53:26.231787 | 
2025-10-13 14:53:26.231889 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-13 14:53:26.835824 | controller -> localhost | changed
2025-10-13 14:53:26.842559 | 
2025-10-13 14:53:26.842657 | TASK [validate-host : Collect information about zuul worker]
2025-10-13 14:53:27.272148 | controller | ok
2025-10-13 14:53:27.278308 | 
2025-10-13 14:53:27.278377 | TASK [validate-host : Write out all zuul information for each host]
2025-10-13 14:53:27.856629 | controller -> localhost | changed
2025-10-13 14:53:27.872944 | 
2025-10-13 14:53:27.873080 | TASK [include_role : prepare-workspace-openshift]
2025-10-13 14:53:27.897797 | controller | skipping: Conditional result was False
2025-10-13 14:53:27.904615 | 
2025-10-13 14:53:27.904715 | TASK [include_role : remove-zuul-sshkey]
2025-10-13 14:53:27.939495 | controller | skipping: Conditional result was False
2025-10-13 14:53:27.944667 | 
2025-10-13 14:53:27.944754 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-13 14:53:28.196323 | controller | ok: "logs"
2025-10-13 14:53:28.196576 | controller | ok: All items complete
2025-10-13 14:53:28.196612 | 
2025-10-13 14:53:28.450554 | controller | ok: "artifacts"
2025-10-13 14:53:28.691510 | controller | ok: "docs"
2025-10-13 14:53:28.698624 | 
2025-10-13 14:53:28.698765 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-13 14:53:29.023890 | controller | changed: "logs"
2025-10-13 14:53:29.237322 | controller | changed: "artifacts"
2025-10-13 14:53:29.457386 | controller | changed: "docs"
2025-10-13 14:53:29.503138 | 
2025-10-13 14:53:29.503238 | PLAY RECAP
2025-10-13 14:53:29.503279 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-13 14:53:29.503304 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-13 14:53:29.503321 | 
2025-10-13 14:53:29.693043 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-13 14:53:29.693938 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-13 14:53:30.369384 | 
2025-10-13 14:53:30.369533 | PLAY [localhost]
2025-10-13 14:53:30.388032 | 
2025-10-13 14:53:30.388148 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-10-13 14:53:30.836898 | localhost | ok
2025-10-13 14:53:30.859556 | 
2025-10-13 14:53:30.859700 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-10-13 14:53:31.711126 | localhost | changed
2025-10-13 14:53:31.736793 | 
2025-10-13 14:53:31.736970 | PLAY [all]
2025-10-13 14:53:31.754886 | 
2025-10-13 14:53:31.755024 | TASK [include_role : prepare-workspace]
2025-10-13 14:53:31.784879 | controller | ok
2025-10-13 14:53:31.800681 | 
2025-10-13 14:53:31.800875 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-13 14:53:32.247377 | controller | ok
2025-10-13 14:53:32.256678 | 
2025-10-13 14:53:32.256823 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-13 14:53:34.898412 | controller | Output suppressed because no_log was given
2025-10-13 14:53:34.913360 | 
2025-10-13 14:53:34.913494 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-13 14:53:35.182958 | controller | changed: "logs"
2025-10-13 14:53:35.397407 | controller | changed: "artifacts"
2025-10-13 14:53:35.701601 | controller | changed: "docs"
2025-10-13 14:53:35.711004 | 
2025-10-13 14:53:35.711086 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-13 14:53:36.005676 | controller | changed: "logs"
2025-10-13 14:53:36.006850 | controller | changed: All items complete
2025-10-13 14:53:36.006921 | 
2025-10-13 14:53:36.232177 | controller | changed: "artifacts"
2025-10-13 14:53:36.496576 | controller | changed: "docs"
2025-10-13 14:53:36.515648 | 
2025-10-13 14:53:36.515803 | TASK [Check if worker can sudo]
2025-10-13 14:53:37.572014 | controller | ok: Runtime: 0:00:00.051671
2025-10-13 14:53:37.588561 | 
2025-10-13 14:53:37.588692 | TASK [configure-mirrors : Gather needed facts]
2025-10-13 14:53:37.882706 | controller | skipping: Conditional result was False
2025-10-13 14:53:37.890058 | 
2025-10-13 14:53:37.890151 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-10-13 14:53:38.014224 | controller | ok
2025-10-13 14:53:38.097250 | controller | included: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-10-13 14:53:38.139224 | 
2025-10-13 14:53:38.139350 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-10-13 14:53:38.420681 | controller | ok
2025-10-13 14:53:38.440268 | 
2025-10-13 14:53:38.440389 | LOOP [configure-mirrors : Include OS-specific variables]
2025-10-13 14:53:38.537381 | controller | ok: "/var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-10-13 14:53:38.557274 | 
2025-10-13 14:53:38.557404 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-10-13 14:53:39.479384 | controller | changed
2025-10-13 14:53:39.485543 | 
2025-10-13 14:53:39.485609 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-10-13 14:53:39.550296 | controller | ok: "/var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-10-13 14:53:39.550556 | controller | ok: All items complete
2025-10-13 14:53:39.550595 | 
2025-10-13 14:53:39.619380 | controller | included: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-10-13 14:53:39.626324 | 
2025-10-13 14:53:39.626402 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-10-13 14:53:40.733572 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-10-13 14:53:41.688800 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-10-13 14:53:41.702460 | 
2025-10-13 14:53:41.702585 | TASK [configure-mirrors : Disable deltrarpm]
2025-10-13 14:53:42.254987 | controller | changed: section and option added
2025-10-13 14:53:42.300255 | 
2025-10-13 14:53:42.300396 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-10-13 14:53:43.095329 | controller | 29 files removed
2025-10-13 14:53:43.095538 | controller | ok: Item: dnf clean all Runtime: 0:00:00.463931
2025-10-13 14:53:43.095578 | controller | changed: All items complete
2025-10-13 14:53:43.095600 | 
2025-10-13 14:53:54.189591 | controller | Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, groups-manager, needs-restarting, notify-packagekit, playground, repoclosure, repodiff, repograph, repomanage, reposync, system-upgrade
2025-10-13 14:53:54.189781 | controller | DNF version: 4.14.0
2025-10-13 14:53:54.189844 | controller | cachedir: /var/cache/dnf
2025-10-13 14:53:54.189876 | controller | Making cache files for all metadata files.
2025-10-13 14:53:54.189924 | controller | baseos: has expired and will be refreshed.
2025-10-13 14:53:54.189952 | controller | appstream: has expired and will be refreshed.
2025-10-13 14:53:54.190017 | controller | crb: has expired and will be refreshed.
2025-10-13 14:53:54.190186 | controller | extras-common: has expired and will be refreshed.
2025-10-13 14:53:54.190219 | controller | repo: downloading from remote: baseos
2025-10-13 14:53:54.190238 | controller | CentOS Stream 9 - BaseOS                         71 MB/s | 8.8 MB     00:00
2025-10-13 14:53:54.190308 | controller | baseos: using metadata from Wed 08 Oct 2025 09:42:12 AM EDT.
2025-10-13 14:53:54.190328 | controller | repo: downloading from remote: appstream
2025-10-13 14:53:54.190372 | controller | CentOS Stream 9 - AppStream                      62 MB/s |  25 MB     00:00
2025-10-13 14:53:54.190393 | controller | appstream: using metadata from Wed 08 Oct 2025 09:45:45 AM EDT.
2025-10-13 14:53:54.190409 | controller | repo: downloading from remote: crb
2025-10-13 14:53:54.190450 | controller | CentOS Stream 9 - CRB                            59 MB/s | 7.2 MB     00:00
2025-10-13 14:53:54.190470 | controller | crb: using metadata from Wed 08 Oct 2025 09:50:07 AM EDT.
2025-10-13 14:53:54.190486 | controller | repo: downloading from remote: extras-common
2025-10-13 14:53:54.190525 | controller | CentOS Stream 9 - Extras packages               1.5 MB/s |  20 kB     00:00
2025-10-13 14:53:54.190547 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT.
2025-10-13 14:53:54.190563 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-10-13 14:53:54.190598 | controller | Completion plugin: Generating completion cache...
2025-10-13 14:53:54.190622 | controller | Metadata cache created.
2025-10-13 14:53:54.190652 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.848128
2025-10-13 14:53:54.212655 | 
2025-10-13 14:53:54.212792 | PLAY RECAP
2025-10-13 14:53:54.212839 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-13 14:53:54.212865 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-13 14:53:54.212882 | 
2025-10-13 14:53:54.341056 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-13 14:53:54.341939 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 14:53:54.983093 | 
2025-10-13 14:53:54.983261 | PLAY [all]
2025-10-13 14:53:55.014525 | 
2025-10-13 14:53:55.014677 | TASK [Install binary dependencies]
2025-10-13 14:53:55.066121 | controller | ok
2025-10-13 14:53:55.086899 | 
2025-10-13 14:53:55.087058 | TASK [bindep : Include find tasks]
2025-10-13 14:53:55.118445 | controller | ok
2025-10-13 14:53:55.126814 | controller | included: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-13 14:53:55.133518 | 
2025-10-13 14:53:55.133638 | TASK [bindep : Look for bindep.txt]
2025-10-13 14:53:55.568158 | controller | ok
2025-10-13 14:53:55.574813 | 
2025-10-13 14:53:55.574953 | TASK [bindep : Define bindep_file fact]
2025-10-13 14:53:55.603988 | controller | ok
2025-10-13 14:53:55.609313 | 
2025-10-13 14:53:55.609402 | TASK [bindep : Look for other-requirements.txt]
2025-10-13 14:53:55.623306 | controller | skipping: Conditional result was False
2025-10-13 14:53:55.632242 | 
2025-10-13 14:53:55.632378 | TASK [bindep : Define bindep_file fact]
2025-10-13 14:53:55.657038 | controller | skipping: Conditional result was False
2025-10-13 14:53:55.664975 | 
2025-10-13 14:53:55.665124 | TASK [bindep : Look for bindep fallback file]
2025-10-13 14:53:55.690014 | controller | skipping: Conditional result was False
2025-10-13 14:53:55.696390 | 
2025-10-13 14:53:55.696480 | TASK [bindep : Define bindep_file fact]
2025-10-13 14:53:55.720204 | controller | skipping: Conditional result was False
2025-10-13 14:53:55.726496 | 
2025-10-13 14:53:55.726574 | TASK [bindep : Include bindep tasks]
2025-10-13 14:53:55.756436 | controller | ok
2025-10-13 14:53:55.763214 | controller | included: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-10-13 14:53:55.771468 | 
2025-10-13 14:53:55.771555 | TASK [bindep : Look for bindep command]
2025-10-13 14:53:55.795327 | controller | skipping: Conditional result was False
2025-10-13 14:53:55.801926 | 
2025-10-13 14:53:55.802020 | TASK [bindep : Check for system bindep]
2025-10-13 14:53:56.336554 | controller | ok: Runtime: 0:00:00.006128
2025-10-13 14:53:56.346579 | 
2025-10-13 14:53:56.346705 | TASK [bindep : Define bindep_command fact]
2025-10-13 14:53:56.373264 | controller | skipping: Conditional result was False
2025-10-13 14:53:56.384062 | 
2025-10-13 14:53:56.384236 | TASK [bindep : Include install tasks]
2025-10-13 14:53:56.428302 | controller | ok
2025-10-13 14:53:56.440118 | controller | included: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-10-13 14:53:56.452223 | 
2025-10-13 14:53:56.452350 | TASK [bindep : Create temp dir for bindep]
2025-10-13 14:53:56.820080 | controller | changed
2025-10-13 14:53:56.825298 | 
2025-10-13 14:53:56.825373 | TASK [Ensure we have pip dependencies]
2025-10-13 14:53:56.844266 | controller | ok
2025-10-13 14:53:56.869048 | 
2025-10-13 14:53:56.869164 | TASK [ensure-pip : Check if pip is installed]
2025-10-13 10:53:57.138868 | controller | /usr/bin/pip3
2025-10-13 10:53:57.162296 | controller | /usr/bin/python3: No module named wheel
2025-10-13 14:53:57.403330 | controller | ok: Runtime: 0:00:00.034271
2025-10-13 14:53:57.409867 | 
2025-10-13 14:53:57.409939 | LOOP [ensure-pip : Install pip from packages]
2025-10-13 14:53:57.436054 | controller | ok: "/var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-10-13 14:53:57.453030 | controller | included: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-10-13 14:53:57.463787 | 
2025-10-13 14:53:57.463886 | TASK [ensure-pip : Install Python 3 pip]
2025-10-13 14:53:59.901679 | controller | changed
2025-10-13 14:53:59.918692 | 
2025-10-13 14:53:59.918876 | TASK [ensure-pip : Check for EPEL repository]
2025-10-13 14:53:59.996477 | controller | skipping: Conditional result was False
2025-10-13 14:54:00.010051 | 
2025-10-13 14:54:00.010193 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-10-13 14:54:00.059040 | controller | skipping: Conditional result was False
2025-10-13 14:54:00.067661 | 
2025-10-13 14:54:00.068164 | TASK [ensure-pip : Install Python 2 pip]
2025-10-13 14:54:00.114792 | controller | skipping: Conditional result was False
2025-10-13 14:54:00.122076 | 
2025-10-13 14:54:00.122147 | TASK [ensure-pip : Ensure setuptools]
2025-10-13 14:54:00.146604 | controller | skipping: Conditional result was False
2025-10-13 14:54:00.152700 | 
2025-10-13 14:54:00.152816 | TASK [ensure-pip : Check for ensurepip module]
2025-10-13 14:54:00.683658 | controller | skipping: Conditional result was False
2025-10-13 14:54:00.697870 | 
2025-10-13 14:54:00.698084 | TASK [ensure-pip : Ensure python3-venv]
2025-10-13 14:54:00.725622 | controller | skipping: Conditional result was False
2025-10-13 14:54:00.736126 | 
2025-10-13 14:54:00.736281 | TASK [ensure-pip : Install pip from source]
2025-10-13 14:54:00.752278 | controller | skipping: Conditional result was False
2025-10-13 14:54:00.762486 | 
2025-10-13 14:54:00.762632 | TASK [ensure-pip : Probe for venv python full path]
2025-10-13 10:54:01.035586 | controller | /usr/bin/python3
2025-10-13 14:54:01.310444 | controller | ok: Runtime: 0:00:00.006784
2025-10-13 14:54:01.319470 | 
2025-10-13 14:54:01.319624 | TASK [ensure-pip : Set host default]
2025-10-13 14:54:01.378381 | controller | ok
2025-10-13 14:54:01.390717 | 
2025-10-13 14:54:01.391338 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-10-13 14:54:01.459566 | controller | ok
2025-10-13 14:54:01.475970 | 
2025-10-13 14:54:01.476110 | TASK [bindep : Install bindep into temporary venv]
2025-10-13 14:54:05.993195 | controller | changed
2025-10-13 14:54:06.005067 | 
2025-10-13 14:54:06.005226 | TASK [bindep : Define bindep_command]
2025-10-13 14:54:06.036901 | controller | ok
2025-10-13 14:54:06.042859 | 
2025-10-13 14:54:06.042955 | LOOP [bindep : Include package tasks]
2025-10-13 14:54:06.094330 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-10-13 14:54:06.094548 | controller | ok: All items complete
2025-10-13 14:54:06.094589 | 
2025-10-13 14:54:06.113476 | controller | included: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-10-13 14:54:06.127487 | 
2025-10-13 14:54:06.127595 | TASK [bindep : Define bindep_run fact]
2025-10-13 14:54:06.148657 | controller | ok
2025-10-13 14:54:06.154597 | 
2025-10-13 14:54:06.154683 | TASK [bindep : Get list of packages to install from bindep]
2025-10-13 10:54:07.770281 | controller | podman
2025-10-13 10:54:07.810677 | controller | python3-jmespath
2025-10-13 10:54:07.810841 | controller | python3-libvirt
2025-10-13 10:54:07.810852 | controller | python3-lxml
2025-10-13 10:54:07.810859 | controller | python3-netaddr
2025-10-13 14:54:08.193429 | controller | ok: Runtime: 0:00:01.383805
2025-10-13 14:54:08.204544 | 
2025-10-13 14:54:08.204794 | TASK [bindep : Install distro packages from bindep]
2025-10-13 14:55:18.941475 | controller | changed
2025-10-13 14:55:18.948401 | 
2025-10-13 14:55:18.948492 | TASK [bindep : Check that packages are installed]
2025-10-13 14:55:21.122024 | controller | ok: Runtime: 0:00:01.599330
2025-10-13 14:55:21.129517 | 
2025-10-13 14:55:21.129642 | TASK [bindep : Fail if we cannot install all packages]
2025-10-13 14:55:21.198124 | controller | skipping: Conditional result was False
2025-10-13 14:55:21.216357 | 
2025-10-13 14:55:21.217450 | TASK [Run test-setup role]
2025-10-13 14:55:21.263427 | controller | ok
2025-10-13 14:55:21.311303 | 
2025-10-13 14:55:21.311427 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-13 14:55:21.612635 | controller | ok
2025-10-13 14:55:21.634163 | 
2025-10-13 14:55:21.634267 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-13 14:55:22.196374 | controller | skipping: Conditional result was False
2025-10-13 14:55:22.238871 | 
2025-10-13 14:55:22.239005 | TASK [bindep : Remove bindep temp dir]
2025-10-13 14:55:22.784327 | controller | ok
2025-10-13 14:55:22.814520 | 
2025-10-13 14:55:22.814615 | PLAY RECAP
2025-10-13 14:55:22.814658 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-10-13 14:55:22.814678 | 
2025-10-13 14:55:23.046950 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 14:55:23.047993 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-13 14:55:24.753749 | 
2025-10-13 14:55:24.753888 | PLAY [all]
2025-10-13 14:55:24.802916 | 
2025-10-13 14:55:24.803051 | TASK [Abort when test_command variable is undefined]
2025-10-13 14:55:24.871263 | controller | skipping: Conditional result was False
2025-10-13 14:55:24.880466 | 
2025-10-13 14:55:24.880592 | TASK [Convert test_command to list]
2025-10-13 14:55:24.948362 | controller | skipping: Conditional result was False
2025-10-13 14:55:24.955688 | 
2025-10-13 14:55:24.955819 | TASK [Use test_command list]
2025-10-13 14:55:25.005839 | controller | ok
2025-10-13 14:55:25.011508 | 
2025-10-13 14:55:25.011595 | LOOP [Run test_command]
2025-10-13 14:55:25.646536 | controller | no check to run
2025-10-13 14:55:25.646716 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.008370
2025-10-13 14:55:25.701427 | 
2025-10-13 14:55:25.701565 | PLAY RECAP
2025-10-13 14:55:25.701611 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-13 14:55:25.701676 | 
2025-10-13 14:55:25.833397 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-13 14:55:25.834597 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 14:55:26.903962 | 
2025-10-13 14:55:26.904095 | PLAY [all]
2025-10-13 14:55:26.995343 | 
2025-10-13 14:55:26.995499 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-13 14:55:27.648532 | controller | changed: non-zero return code
2025-10-13 14:55:27.656777 | 
2025-10-13 14:55:27.656902 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-13 14:55:27.739905 | controller | skipping: Conditional result was False
2025-10-13 14:55:27.745609 | 
2025-10-13 14:55:27.745691 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-13 14:55:27.810484 | 
2025-10-13 14:55:27.810642 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-13 14:55:27.869445 | 
2025-10-13 14:55:27.869669 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-13 14:55:27.907675 | controller | skipping: Conditional result was False
2025-10-13 14:55:27.914933 | 
2025-10-13 14:55:27.915059 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-13 14:55:27.977973 | 
2025-10-13 14:55:27.978226 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-13 14:55:28.057819 | controller | skipping: Conditional result was False
2025-10-13 14:55:28.063699 | 
2025-10-13 14:55:28.063806 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-13 14:55:28.098719 | controller | skipping: Conditional result was False
2025-10-13 14:55:28.104851 | 
2025-10-13 14:55:28.104959 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-13 14:55:28.139588 | controller | skipping: Conditional result was False
2025-10-13 14:55:28.168843 | 
2025-10-13 14:55:28.168941 | PLAY RECAP
2025-10-13 14:55:28.168982 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-13 14:55:28.169002 | 
2025-10-13 14:55:28.296506 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 14:55:28.297444 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-13 14:55:32.753443 | 
2025-10-13 14:55:32.753575 | PLAY [all]
2025-10-13 14:55:32.789204 | 
2025-10-13 14:55:32.789357 | TASK [include_role : fetch-output]
2025-10-13 14:55:32.865823 | controller | ok
2025-10-13 14:55:32.909525 | 
2025-10-13 14:55:32.909672 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-13 14:55:32.995782 | controller | skipping: Conditional result was False
2025-10-13 14:55:33.002290 | 
2025-10-13 14:55:33.002430 | TASK [fetch-output : Set log path for single node]
2025-10-13 14:55:33.042697 | controller | ok
2025-10-13 14:55:33.048427 | 
2025-10-13 14:55:33.048522 | LOOP [fetch-output : Ensure local output dirs]
2025-10-13 14:55:33.563139 | controller -> localhost | ok: "/var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/work/logs"
2025-10-13 14:55:33.906062 | controller -> localhost | changed: "/var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/work/artifacts"
2025-10-13 14:55:34.193972 | controller -> localhost | changed: "/var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/work/docs"
2025-10-13 14:55:34.207115 | 
2025-10-13 14:55:34.211234 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-13 14:55:34.884543 | controller | changed: .d..t...... ./
2025-10-13 14:55:34.884766 | controller | changed: All items complete
2025-10-13 14:55:34.884799 | 
2025-10-13 14:55:35.593754 | controller | changed: .d..t...... ./
2025-10-13 14:55:36.276775 | controller | changed: .d..t...... ./
2025-10-13 14:55:36.292068 | 
2025-10-13 14:55:36.292204 | TASK [include_role : fetch-output-openshift]
2025-10-13 14:55:36.316740 | controller | skipping: Conditional result was False
2025-10-13 14:55:36.322931 | 
2025-10-13 14:55:36.323049 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-13 14:55:36.801474 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.012238
2025-10-13 14:55:37.131093 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.008727
2025-10-13 14:55:37.174214 | 
2025-10-13 14:55:37.174364 | PLAY [all]
2025-10-13 14:55:37.199818 | 
2025-10-13 14:55:37.199965 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-13 14:55:37.650746 | controller | changed
2025-10-13 14:55:37.697150 | 
2025-10-13 14:55:37.697256 | PLAY RECAP
2025-10-13 14:55:37.697299 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-13 14:55:37.697321 | 
2025-10-13 14:55:37.817987 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-13 14:55:37.819094 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-13 14:55:38.502027 | 
2025-10-13 14:55:38.502168 | PLAY [localhost]
2025-10-13 14:55:38.523774 | 
2025-10-13 14:55:38.523914 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-13 14:55:38.929284 | localhost | changed
2025-10-13 14:55:38.934093 | 
2025-10-13 14:55:38.934200 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-13 14:55:38.962805 | localhost | ok
2025-10-13 14:55:38.976776 | 
2025-10-13 14:55:38.976925 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-13 14:55:39.369020 | localhost | changed
2025-10-13 14:55:39.376032 | 
2025-10-13 14:55:39.376164 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-13 14:55:40.099598 | localhost | changed
2025-10-13 14:55:40.105602 | 
2025-10-13 14:55:40.105711 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-13 14:55:40.520412 | localhost | Identity added: /var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/work/tmp/ansible.hq9xkamq (/var/lib/zuul/builds/b23ac3699c634dcca43edf9504037a43/work/tmp/ansible.hq9xkamq)
2025-10-13 14:55:40.520609 | localhost | ok: Runtime: 0:00:00.023352
2025-10-13 14:55:40.525228 | 
2025-10-13 14:55:40.525295 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-13 14:55:40.976505 | localhost | ok: Runtime: 0:00:00.007343
2025-10-13 14:55:40.982096 | 
2025-10-13 14:55:40.982221 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-13 14:55:41.032986 | localhost | changed
2025-10-13 14:55:41.038830 | 
2025-10-13 14:55:41.038907 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-13 14:55:41.547529 | localhost | changed
2025-10-13 14:55:41.571091 | 
2025-10-13 14:55:41.571194 | PLAY [localhost]
2025-10-13 14:55:41.585505 | 
2025-10-13 14:55:41.585622 | TASK [Generate bulk log download script]
2025-10-13 14:55:41.615046 | localhost | ok
2025-10-13 14:55:41.630029 | 
2025-10-13 14:55:41.630123 | TASK [local-log-download : Check API endpoint is defined]
2025-10-13 14:55:41.671035 | localhost | ok: All assertions passed
2025-10-13 14:55:41.682812 | 
2025-10-13 14:55:41.682910 | TASK [local-log-download : Create download script]
2025-10-13 14:55:42.469738 | localhost -> localhost | changed
2025-10-13 14:55:42.487204 | 
2025-10-13 14:55:42.487346 | TASK [Register quick-download link]
2025-10-13 14:55:42.532522 | localhost | ok
2025-10-13 14:55:42.613501 | 
2025-10-13 14:55:42.615782 | PLAY [logserver.rdoproject.org]
2025-10-13 14:55:42.627221 | 
2025-10-13 14:55:42.627342 | TASK [Set zuul-log-path fact]
2025-10-13 14:55:42.654711 | logserver.rdoproject.org | ok
2025-10-13 14:55:42.669079 | 
2025-10-13 14:55:42.669195 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 14:55:42.695988 | logserver.rdoproject.org | ok
2025-10-13 14:55:42.701888 | 
2025-10-13 14:55:42.701997 | TASK [upload-logs : Create log directories]
2025-10-13 14:55:43.394680 | logserver.rdoproject.org | changed
2025-10-13 14:55:43.398947 | 
2025-10-13 14:55:43.399065 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-13 14:55:43.799900 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.006420
2025-10-13 14:55:43.805601 | 
2025-10-13 14:55:43.805683 | TASK [upload-logs : Upload logs to log server]
2025-10-13 14:55:44.555394 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-13 14:55:44.558586 | 
2025-10-13 14:55:44.558648 | LOOP [upload-logs : Compress console log and json output]
2025-10-13 14:55:44.616044 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 14:55:44.616886 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 14:55:44.628078 | 
2025-10-13 14:55:44.628157 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-13 14:55:44.664714 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 14:55:44.664967 | 
2025-10-13 14:55:44.669295 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 14:55:44.677050 | 
2025-10-13 14:55:44.677120 | LOOP [upload-logs : Upload console log and json output]