2025-12-01 09:02:09.829998 | Job console starting...
2025-12-01 09:02:09.839391 | Updating repositories
2025-12-01 09:02:09.875381 | Preparing job workspace
2025-12-01 09:02:13.498667 | Running Ansible setup...
2025-12-01 09:02:17.487757 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-12-01 09:02:18.061810 | 
2025-12-01 09:02:18.061933 | PLAY [localhost]
2025-12-01 09:02:18.071287 | 
2025-12-01 09:02:18.071371 | TASK [Gathering Facts]
2025-12-01 09:02:19.105610 | localhost | ok
2025-12-01 09:02:19.148465 | 
2025-12-01 09:02:19.148639 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-12-01 09:02:19.632889 | localhost -> localhost | changed
2025-12-01 09:02:19.644856 | 
2025-12-01 09:02:19.645070 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-12-01 09:02:20.535348 | localhost -> localhost | changed
2025-12-01 09:02:20.563493 | 
2025-12-01 09:02:20.563613 | TASK [Setup log path fact]
2025-12-01 09:02:20.582862 | localhost | ok
2025-12-01 09:02:20.596047 | 
2025-12-01 09:02:20.596123 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-01 09:02:20.634341 | localhost | ok
2025-12-01 09:02:20.642591 | 
2025-12-01 09:02:20.642660 | TASK [emit-job-header : Print job information]
2025-12-01 09:02:20.690845 | # Job Information
2025-12-01 09:02:20.691001 | Ansible Version: 2.15.12
2025-12-01 09:02:20.691112 | Job: cifmw-molecule-cifmw_setup
2025-12-01 09:02:20.691139 | Pipeline: github-check
2025-12-01 09:02:20.691158 | Executor: ze01.softwarefactory-project.io
2025-12-01 09:02:20.691177 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3505
2025-12-01 09:02:20.691206 | Log URL (when completed): https://logserver.rdoproject.org/548/rdoproject.org/54854547eba84d6fb31b19119522424b/
2025-12-01 09:02:20.691232 | Event ID: 44f1e2f0-ce94-11f0-8bee-9ee9a0e8ee70
2025-12-01 09:02:20.694888 | 
2025-12-01 09:02:20.694948 | LOOP [emit-job-header : Print node information]
2025-12-01 09:02:20.802341 | localhost | ok:
2025-12-01 09:02:20.802554 | localhost | # Node Information
2025-12-01 09:02:20.802581 | localhost | Inventory Hostname: controller
2025-12-01 09:02:20.802602 | localhost | Hostname: np0005540814
2025-12-01 09:02:20.802621 | localhost | Username: zuul
2025-12-01 09:02:20.802640 | localhost | Distro: CentOS 9
2025-12-01 09:02:20.802658 | localhost | Provider: vexxhost-nodepool-tripleo
2025-12-01 09:02:20.802675 | localhost | Region: RegionOne
2025-12-01 09:02:20.802691 | localhost | Label: cloud-centos-9-stream-tripleo
2025-12-01 09:02:20.802707 | localhost | Product Name: OpenStack Nova
2025-12-01 09:02:20.802723 | localhost | Interface IP: 38.102.83.142
2025-12-01 09:02:20.829904 | 
2025-12-01 09:02:20.830076 | PLAY [all]
2025-12-01 09:02:20.836603 | 
2025-12-01 09:02:20.836668 | TASK [Gather network facts]
2025-12-01 09:02:21.387380 | controller | ok
2025-12-01 09:02:21.412375 | 
2025-12-01 09:02:21.412483 | TASK [include_role : start-zuul-console]
2025-12-01 09:02:21.435231 | controller | ok
2025-12-01 09:02:21.453115 | 
2025-12-01 09:02:21.453279 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-12-01 09:02:21.896501 | controller | ok
2025-12-01 09:02:21.931843 | 
2025-12-01 09:02:21.932005 | TASK [include_role : add-build-sshkey]
2025-12-01 09:02:21.958877 | controller | ok
2025-12-01 09:02:21.987868 | 
2025-12-01 09:02:21.987995 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-01 09:02:22.278382 | controller -> localhost | ok
2025-12-01 09:02:22.284250 | 
2025-12-01 09:02:22.284328 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-01 09:02:22.314945 | controller | ok
2025-12-01 09:02:22.329028 | controller | included: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-01 09:02:22.335266 | 
2025-12-01 09:02:22.335343 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-01 09:02:22.919203 | controller -> localhost | Generating public/private rsa key pair.
2025-12-01 09:02:22.919422 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/work/54854547eba84d6fb31b19119522424b_id_rsa.
2025-12-01 09:02:22.919453 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/work/54854547eba84d6fb31b19119522424b_id_rsa.pub.
2025-12-01 09:02:22.919475 | controller -> localhost | The key fingerprint is:
2025-12-01 09:02:22.919495 | controller -> localhost | SHA256:3bND4Nbms4qg9GLRr1mkzk7FX2kHNgsspV+jGcUCjW0 zuul-build-sshkey
2025-12-01 09:02:22.919513 | controller -> localhost | The key's randomart image is:
2025-12-01 09:02:22.919531 | controller -> localhost | +---[RSA 3072]----+
2025-12-01 09:02:22.919549 | controller -> localhost | |        .=...    |
2025-12-01 09:02:22.919603 | controller -> localhost | |        .+E..    |
2025-12-01 09:02:22.919625 | controller -> localhost | |        o.=.*    |
2025-12-01 09:02:22.919643 | controller -> localhost | |       . = @ *   |
2025-12-01 09:02:22.919709 | controller -> localhost | |     .  S B @ .  |
2025-12-01 09:02:22.919730 | controller -> localhost | |    . .+ o * +   |
2025-12-01 09:02:22.919782 | controller -> localhost | |    ..+.. . =    |
2025-12-01 09:02:22.919807 | controller -> localhost | |   .o* +..   +   |
2025-12-01 09:02:22.919825 | controller -> localhost | |   ..oB.. ...    |
2025-12-01 09:02:22.919842 | controller -> localhost | +----[SHA256]-----+
2025-12-01 09:02:22.919887 | controller -> localhost | ok: Runtime: 0:00:00.179304
2025-12-01 09:02:22.925564 | 
2025-12-01 09:02:22.925627 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-01 09:02:22.955311 | controller | ok
2025-12-01 09:02:22.966851 | controller | included: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-01 09:02:22.976382 | 
2025-12-01 09:02:22.976523 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-01 09:02:22.991120 | controller | skipping: Conditional result was False
2025-12-01 09:02:23.002729 | 
2025-12-01 09:02:23.002844 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-01 09:02:23.495951 | controller | changed
2025-12-01 09:02:23.504350 | 
2025-12-01 09:02:23.504487 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-01 09:02:23.791998 | controller | ok
2025-12-01 09:02:23.798657 | 
2025-12-01 09:02:23.798805 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-01 09:02:24.679959 | controller | changed
2025-12-01 09:02:24.688973 | 
2025-12-01 09:02:24.689127 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-01 09:02:25.632232 | controller | changed
2025-12-01 09:02:25.646356 | 
2025-12-01 09:02:25.646517 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-01 09:02:25.682149 | controller | skipping: Conditional result was False
2025-12-01 09:02:25.695770 | 
2025-12-01 09:02:25.696042 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-01 09:02:26.138968 | controller -> localhost | changed
2025-12-01 09:02:26.148970 | 
2025-12-01 09:02:26.149064 | TASK [add-build-sshkey : Add back temp key]
2025-12-01 09:02:26.448398 | controller -> localhost | Identity added: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/work/54854547eba84d6fb31b19119522424b_id_rsa (zuul-build-sshkey)
2025-12-01 09:02:26.448682 | controller -> localhost | ok: Runtime: 0:00:00.008112
2025-12-01 09:02:26.454980 | 
2025-12-01 09:02:26.455070 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-01 09:02:26.851476 | controller | ok
2025-12-01 09:02:26.862534 | 
2025-12-01 09:02:26.862701 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-01 09:02:26.901226 | controller | skipping: Conditional result was False
2025-12-01 09:02:26.915575 | 
2025-12-01 09:02:26.915720 | TASK [include_role : validate-host]
2025-12-01 09:02:26.950100 | controller | ok
2025-12-01 09:02:26.981915 | 
2025-12-01 09:02:26.982084 | TASK [validate-host : Define zuul_info_dir fact]
2025-12-01 09:02:27.012183 | controller | ok
2025-12-01 09:02:27.017008 | 
2025-12-01 09:02:27.017113 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-12-01 09:02:27.267542 | controller -> localhost | ok
2025-12-01 09:02:27.275946 | 
2025-12-01 09:02:27.276071 | TASK [validate-host : Collect information about the host]
2025-12-01 09:02:28.160273 | controller | ok
2025-12-01 09:02:28.178294 | 
2025-12-01 09:02:28.178441 | TASK [validate-host : Sanitize hostname]
2025-12-01 09:02:28.255943 | controller | ok
2025-12-01 09:02:28.267368 | 
2025-12-01 09:02:28.267517 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-12-01 09:02:28.827079 | controller -> localhost | changed
2025-12-01 09:02:28.835249 | 
2025-12-01 09:02:28.835395 | TASK [validate-host : Collect information about zuul worker]
2025-12-01 09:02:29.245283 | controller | ok
2025-12-01 09:02:29.252416 | 
2025-12-01 09:02:29.252517 | TASK [validate-host : Write out all zuul information for each host]
2025-12-01 09:02:29.802272 | controller -> localhost | changed
2025-12-01 09:02:29.825393 | 
2025-12-01 09:02:29.825534 | TASK [include_role : prepare-workspace-openshift]
2025-12-01 09:02:29.841045 | controller | skipping: Conditional result was False
2025-12-01 09:02:29.849163 | 
2025-12-01 09:02:29.849309 | TASK [include_role : remove-zuul-sshkey]
2025-12-01 09:02:29.864371 | controller | skipping: Conditional result was False
2025-12-01 09:02:29.872529 | 
2025-12-01 09:02:29.872632 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-12-01 09:02:30.178087 | controller | ok: "logs"
2025-12-01 09:02:30.178479 | controller | ok: All items complete
2025-12-01 09:02:30.178552 | 
2025-12-01 09:02:30.387956 | controller | ok: "artifacts"
2025-12-01 09:02:30.673609 | controller | ok: "docs"
2025-12-01 09:02:30.688513 | 
2025-12-01 09:02:30.690875 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-12-01 09:02:31.030255 | controller | changed: "logs"
2025-12-01 09:02:31.306239 | controller | changed: "artifacts"
2025-12-01 09:02:31.519577 | controller | changed: "docs"
2025-12-01 09:02:31.557962 | 
2025-12-01 09:02:31.558089 | PLAY RECAP
2025-12-01 09:02:31.558134 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-12-01 09:02:31.558159 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-01 09:02:31.558177 | 
2025-12-01 09:02:31.678147 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-12-01 09:02:31.679662 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-12-01 09:02:32.324953 | 
2025-12-01 09:02:32.325094 | PLAY [localhost]
2025-12-01 09:02:32.342148 | 
2025-12-01 09:02:32.342249 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-12-01 09:02:32.752990 | localhost | ok
2025-12-01 09:02:32.766990 | 
2025-12-01 09:02:32.767215 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-12-01 09:02:33.518102 | localhost | changed
2025-12-01 09:02:33.538376 | 
2025-12-01 09:02:33.538449 | PLAY [all]
2025-12-01 09:02:33.553915 | 
2025-12-01 09:02:33.554008 | TASK [include_role : prepare-workspace]
2025-12-01 09:02:33.573616 | controller | ok
2025-12-01 09:02:33.589893 | 
2025-12-01 09:02:33.590009 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-12-01 09:02:34.009118 | controller | ok
2025-12-01 09:02:34.026338 | 
2025-12-01 09:02:34.026654 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-12-01 09:02:35.959886 | controller | Output suppressed because no_log was given
2025-12-01 09:02:35.974312 | 
2025-12-01 09:02:35.974456 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-12-01 09:02:36.266910 | controller | changed: "logs"
2025-12-01 09:02:36.525331 | controller | changed: "artifacts"
2025-12-01 09:02:36.755380 | controller | changed: "docs"
2025-12-01 09:02:36.784334 | 
2025-12-01 09:02:36.784701 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-12-01 09:02:37.094241 | controller | changed: "logs"
2025-12-01 09:02:37.094997 | controller | changed: All items complete
2025-12-01 09:02:37.095118 | 
2025-12-01 09:02:37.378284 | controller | changed: "artifacts"
2025-12-01 09:02:37.633269 | controller | changed: "docs"
2025-12-01 09:02:37.655915 | 
2025-12-01 09:02:37.656122 | TASK [Check if worker can sudo]
2025-12-01 09:02:38.195587 | controller | ok: Runtime: 0:00:00.040078
2025-12-01 09:02:38.209172 | 
2025-12-01 09:02:38.209330 | TASK [configure-mirrors : Gather needed facts]
2025-12-01 09:02:38.307884 | controller | skipping: Conditional result was False
2025-12-01 09:02:38.321829 | 
2025-12-01 09:02:38.321988 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-12-01 09:02:38.448334 | controller | ok
2025-12-01 09:02:38.461474 | controller | included: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-12-01 09:02:38.501395 | 
2025-12-01 09:02:38.501540 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-12-01 09:02:38.775344 | controller | ok
2025-12-01 09:02:38.781262 | 
2025-12-01 09:02:38.781330 | LOOP [configure-mirrors : Include OS-specific variables]
2025-12-01 09:02:38.876585 | controller | ok: "/var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-12-01 09:02:38.896602 | 
2025-12-01 09:02:38.896816 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-12-01 09:02:39.911039 | controller | changed
2025-12-01 09:02:39.916470 | 
2025-12-01 09:02:39.916543 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-12-01 09:02:39.973223 | controller | ok: "/var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-12-01 09:02:39.973394 | controller | ok: All items complete
2025-12-01 09:02:39.973420 | 
2025-12-01 09:02:40.029870 | controller | included: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-12-01 09:02:40.041782 | 
2025-12-01 09:02:40.041883 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-12-01 09:02:40.959650 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-12-01 09:02:41.901564 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-12-01 09:02:41.915370 | 
2025-12-01 09:02:41.915469 | TASK [configure-mirrors : Disable deltrarpm]
2025-12-01 09:02:42.420388 | controller | changed: section and option added
2025-12-01 09:02:42.459859 | 
2025-12-01 09:02:42.460002 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-12-01 09:02:43.127763 | controller | 29 files removed
2025-12-01 09:02:43.128399 | controller | ok: Item: dnf clean all Runtime: 0:00:00.311997
2025-12-01 09:02:43.128521 | controller | changed: All items complete
2025-12-01 09:02:43.128573 | 
2025-12-01 09:02:53.430637 | controller | Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, groups-manager, needs-restarting, playground, repoclosure, repodiff, repograph, repomanage, reposync, system-upgrade
2025-12-01 09:02:53.430810 | controller | DNF version: 4.14.0
2025-12-01 09:02:53.430863 | controller | cachedir: /var/cache/dnf
2025-12-01 09:02:53.430906 | controller | Making cache files for all metadata files.
2025-12-01 09:02:53.430945 | controller | baseos: has expired and will be refreshed.
2025-12-01 09:02:53.430983 | controller | appstream: has expired and will be refreshed.
2025-12-01 09:02:53.431046 | controller | crb: has expired and will be refreshed.
2025-12-01 09:02:53.431107 | controller | extras-common: has expired and will be refreshed.
2025-12-01 09:02:53.431145 | controller | repo: downloading from remote: baseos
2025-12-01 09:02:53.431181 | controller | CentOS Stream 9 - BaseOS                         63 MB/s | 8.8 MB     00:00
2025-12-01 09:02:53.431217 | controller | baseos: using metadata from Mon 24 Nov 2025 12:32:03 PM EST.
2025-12-01 09:02:53.431253 | controller | repo: downloading from remote: appstream
2025-12-01 09:02:53.431289 | controller | CentOS Stream 9 - AppStream                      94 MB/s |  25 MB     00:00
2025-12-01 09:02:53.431324 | controller | appstream: using metadata from Mon 24 Nov 2025 12:35:27 PM EST.
2025-12-01 09:02:53.431359 | controller | repo: downloading from remote: crb
2025-12-01 09:02:53.431393 | controller | CentOS Stream 9 - CRB                            72 MB/s | 7.3 MB     00:00
2025-12-01 09:02:53.431430 | controller | crb: using metadata from Mon 24 Nov 2025 12:39:46 PM EST.
2025-12-01 09:02:53.431464 | controller | repo: downloading from remote: extras-common
2025-12-01 09:02:53.431499 | controller | CentOS Stream 9 - Extras packages               1.6 MB/s |  20 kB     00:00
2025-12-01 09:02:53.431534 | controller | extras-common: using metadata from Thu 30 Oct 2025 09:20:08 AM EDT.
2025-12-01 09:02:53.431569 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-12-01 09:02:53.431604 | controller | Completion plugin: Generating completion cache...
2025-12-01 09:02:53.431638 | controller | Metadata cache created.
2025-12-01 09:02:53.431693 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.010604
2025-12-01 09:02:53.462542 | 
2025-12-01 09:02:53.462698 | PLAY RECAP
2025-12-01 09:02:53.462783 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-12-01 09:02:53.462840 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-01 09:02:53.462879 | 
2025-12-01 09:02:53.588482 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-12-01 09:02:53.589399 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-01 09:02:54.198864 | 
2025-12-01 09:02:54.198985 | PLAY [all]
2025-12-01 09:02:54.220573 | 
2025-12-01 09:02:54.220691 | TASK [Install binary dependencies]
2025-12-01 09:02:54.270032 | controller | ok
2025-12-01 09:02:54.289169 | 
2025-12-01 09:02:54.289266 | TASK [bindep : Include find tasks]
2025-12-01 09:02:54.328684 | controller | ok
2025-12-01 09:02:54.336551 | controller | included: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-12-01 09:02:54.342764 | 
2025-12-01 09:02:54.342831 | TASK [bindep : Look for bindep.txt]
2025-12-01 09:02:54.875885 | controller | ok
2025-12-01 09:02:54.882741 | 
2025-12-01 09:02:54.882826 | TASK [bindep : Define bindep_file fact]
2025-12-01 09:02:54.922047 | controller | ok
2025-12-01 09:02:54.927056 | 
2025-12-01 09:02:54.927126 | TASK [bindep : Look for other-requirements.txt]
2025-12-01 09:02:54.951395 | controller | skipping: Conditional result was False
2025-12-01 09:02:54.968314 | 
2025-12-01 09:02:54.968473 | TASK [bindep : Define bindep_file fact]
2025-12-01 09:02:55.014628 | controller | skipping: Conditional result was False
2025-12-01 09:02:55.024454 | 
2025-12-01 09:02:55.024563 | TASK [bindep : Look for bindep fallback file]
2025-12-01 09:02:55.070608 | controller | skipping: Conditional result was False
2025-12-01 09:02:55.078947 | 
2025-12-01 09:02:55.079087 | TASK [bindep : Define bindep_file fact]
2025-12-01 09:02:55.104351 | controller | skipping: Conditional result was False
2025-12-01 09:02:55.115162 | 
2025-12-01 09:02:55.115289 | TASK [bindep : Include bindep tasks]
2025-12-01 09:02:55.150590 | controller | ok
2025-12-01 09:02:55.160838 | controller | included: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-12-01 09:02:55.173146 | 
2025-12-01 09:02:55.173255 | TASK [bindep : Look for bindep command]
2025-12-01 09:02:55.199394 | controller | skipping: Conditional result was False
2025-12-01 09:02:55.210838 | 
2025-12-01 09:02:55.211105 | TASK [bindep : Check for system bindep]
2025-12-01 09:02:55.766225 | controller | ok: Runtime: 0:00:00.006491
2025-12-01 09:02:55.772353 | 
2025-12-01 09:02:55.772436 | TASK [bindep : Define bindep_command fact]
2025-12-01 09:02:55.807715 | controller | skipping: Conditional result was False
2025-12-01 09:02:55.814508 | 
2025-12-01 09:02:55.814585 | TASK [bindep : Include install tasks]
2025-12-01 09:02:55.862793 | controller | ok
2025-12-01 09:02:55.881508 | controller | included: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-12-01 09:02:55.894499 | 
2025-12-01 09:02:55.894642 | TASK [bindep : Create temp dir for bindep]
2025-12-01 09:02:56.303793 | controller | changed
2025-12-01 09:02:56.309352 | 
2025-12-01 09:02:56.309414 | TASK [Ensure we have pip dependencies]
2025-12-01 09:02:56.329441 | controller | ok
2025-12-01 09:02:56.353419 | 
2025-12-01 09:02:56.353520 | TASK [ensure-pip : Check if pip is installed]
2025-12-01 04:02:56.618729 | controller | /usr/bin/pip3
2025-12-01 04:02:56.639478 | controller | /usr/bin/python3: No module named wheel
2025-12-01 09:02:56.884154 | controller | ok: Runtime: 0:00:00.028858
2025-12-01 09:02:56.900174 | 
2025-12-01 09:02:56.900375 | LOOP [ensure-pip : Install pip from packages]
2025-12-01 09:02:56.949345 | controller | ok: "/var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-12-01 09:02:56.969815 | controller | included: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-12-01 09:02:56.987303 | 
2025-12-01 09:02:56.987432 | TASK [ensure-pip : Install Python 3 pip]
2025-12-01 09:02:58.732231 | controller | changed
2025-12-01 09:02:58.743890 | 
2025-12-01 09:02:58.744049 | TASK [ensure-pip : Check for EPEL repository]
2025-12-01 09:02:58.811255 | controller | skipping: Conditional result was False
2025-12-01 09:02:58.823673 | 
2025-12-01 09:02:58.823832 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-12-01 09:02:58.881972 | controller | skipping: Conditional result was False
2025-12-01 09:02:58.894579 | 
2025-12-01 09:02:58.894718 | TASK [ensure-pip : Install Python 2 pip]
2025-12-01 09:02:58.962286 | controller | skipping: Conditional result was False
2025-12-01 09:02:58.986517 | 
2025-12-01 09:02:58.986701 | TASK [ensure-pip : Ensure setuptools]
2025-12-01 09:02:59.013522 | controller | skipping: Conditional result was False
2025-12-01 09:02:59.030671 | 
2025-12-01 09:02:59.030858 | TASK [ensure-pip : Check for ensurepip module]
2025-12-01 09:02:59.580441 | controller | skipping: Conditional result was False
2025-12-01 09:02:59.588725 | 
2025-12-01 09:02:59.588820 | TASK [ensure-pip : Ensure python3-venv]
2025-12-01 09:02:59.624011 | controller | skipping: Conditional result was False
2025-12-01 09:02:59.632696 | 
2025-12-01 09:02:59.632795 | TASK [ensure-pip : Install pip from source]
2025-12-01 09:02:59.661455 | controller | skipping: Conditional result was False
2025-12-01 09:02:59.667205 | 
2025-12-01 09:02:59.667312 | TASK [ensure-pip : Probe for venv python full path]
2025-12-01 04:02:59.923297 | controller | /usr/bin/python3
2025-12-01 09:03:00.196906 | controller | ok: Runtime: 0:00:00.008957
2025-12-01 09:03:00.209160 | 
2025-12-01 09:03:00.209327 | TASK [ensure-pip : Set host default]
2025-12-01 09:03:00.308668 | controller | ok
2025-12-01 09:03:00.319544 | 
2025-12-01 09:03:00.319632 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-12-01 09:03:00.397545 | controller | ok
2025-12-01 09:03:00.422869 | 
2025-12-01 09:03:00.423096 | TASK [bindep : Install bindep into temporary venv]
2025-12-01 09:03:04.698507 | controller | changed
2025-12-01 09:03:04.710121 | 
2025-12-01 09:03:04.710255 | TASK [bindep : Define bindep_command]
2025-12-01 09:03:04.749966 | controller | ok
2025-12-01 09:03:04.761182 | 
2025-12-01 09:03:04.761314 | LOOP [bindep : Include package tasks]
2025-12-01 09:03:04.835291 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-12-01 09:03:04.835587 | controller | ok: All items complete
2025-12-01 09:03:04.835646 | 
2025-12-01 09:03:04.857956 | controller | included: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-12-01 09:03:04.879946 | 
2025-12-01 09:03:04.880109 | TASK [bindep : Define bindep_run fact]
2025-12-01 09:03:04.912249 | controller | ok
2025-12-01 09:03:04.919807 | 
2025-12-01 09:03:04.919932 | TASK [bindep : Get list of packages to install from bindep]
2025-12-01 04:03:06.222677 | controller | podman
2025-12-01 04:03:06.258165 | controller | python3-jmespath
2025-12-01 04:03:06.258308 | controller | python3-libvirt
2025-12-01 04:03:06.258319 | controller | python3-lxml
2025-12-01 04:03:06.258326 | controller | python3-netaddr
2025-12-01 09:03:06.464638 | controller | ok: Runtime: 0:00:01.075404
2025-12-01 09:03:06.477253 | 
2025-12-01 09:03:06.477394 | TASK [bindep : Install distro packages from bindep]
2025-12-01 09:04:06.803750 | controller | changed
2025-12-01 09:04:06.816495 | 
2025-12-01 09:04:06.816666 | TASK [bindep : Check that packages are installed]
2025-12-01 09:04:08.371437 | controller | ok: Runtime: 0:00:01.048355
2025-12-01 09:04:08.412093 | 
2025-12-01 09:04:08.412428 | TASK [bindep : Fail if we cannot install all packages]
2025-12-01 09:04:08.447975 | controller | skipping: Conditional result was False
2025-12-01 09:04:08.463815 | 
2025-12-01 09:04:08.463939 | TASK [Run test-setup role]
2025-12-01 09:04:08.486908 | controller | ok
2025-12-01 09:04:08.511343 | 
2025-12-01 09:04:08.511482 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-12-01 09:04:08.734746 | controller | ok
2025-12-01 09:04:08.745877 | 
2025-12-01 09:04:08.746042 | TASK [test-setup : Run tools/test-setup.sh]
2025-12-01 09:04:09.306484 | controller | skipping: Conditional result was False
2025-12-01 09:04:09.345427 | 
2025-12-01 09:04:09.347078 | TASK [bindep : Remove bindep temp dir]
2025-12-01 09:04:09.702291 | controller | ok
2025-12-01 09:04:09.712303 | 
2025-12-01 09:04:09.712357 | PLAY RECAP
2025-12-01 09:04:09.712399 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-12-01 09:04:09.712421 | 
2025-12-01 09:04:09.805312 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-01 09:04:09.807207 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-12-01 09:04:10.408928 | 
2025-12-01 09:04:10.409047 | PLAY [all]
2025-12-01 09:04:10.429794 | 
2025-12-01 09:04:10.429900 | TASK [Abort when test_command variable is undefined]
2025-12-01 09:04:10.464308 | controller | skipping: Conditional result was False
2025-12-01 09:04:10.470203 | 
2025-12-01 09:04:10.470276 | TASK [Convert test_command to list]
2025-12-01 09:04:10.524468 | controller | skipping: Conditional result was False
2025-12-01 09:04:10.537420 | 
2025-12-01 09:04:10.537562 | TASK [Use test_command list]
2025-12-01 09:04:10.594654 | controller | ok
2025-12-01 09:04:10.606509 | 
2025-12-01 09:04:10.606653 | LOOP [Run test_command]
2025-12-01 09:04:11.003181 | controller | no check to run
2025-12-01 09:04:11.003586 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.005031
2025-12-01 09:04:11.032410 | 
2025-12-01 09:04:11.032529 | PLAY RECAP
2025-12-01 09:04:11.032570 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-12-01 09:04:11.032590 | 
2025-12-01 09:04:11.128771 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-12-01 09:04:11.130496 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-01 09:04:11.694272 | 
2025-12-01 09:04:11.694394 | PLAY [all]
2025-12-01 09:04:11.714992 | 
2025-12-01 09:04:11.715103 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-12-01 09:04:12.213295 | controller | changed: non-zero return code
2025-12-01 09:04:12.239295 | 
2025-12-01 09:04:12.239528 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-12-01 09:04:12.265551 | controller | skipping: Conditional result was False
2025-12-01 09:04:12.274707 | 
2025-12-01 09:04:12.274814 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-12-01 09:04:12.317661 | 
2025-12-01 09:04:12.317841 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-12-01 09:04:12.349849 | 
2025-12-01 09:04:12.350075 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-12-01 09:04:12.374151 | controller | skipping: Conditional result was False
2025-12-01 09:04:12.382315 | 
2025-12-01 09:04:12.382406 | LOOP [fetch-subunit-output : Generate subunit file]
2025-12-01 09:04:12.424900 | 
2025-12-01 09:04:12.425099 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-12-01 09:04:12.449473 | controller | skipping: Conditional result was False
2025-12-01 09:04:12.458056 | 
2025-12-01 09:04:12.458157 | TASK [fetch-subunit-output : Remove the temporary file]
2025-12-01 09:04:12.488550 | controller | skipping: Conditional result was False
2025-12-01 09:04:12.496580 | 
2025-12-01 09:04:12.496665 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-12-01 09:04:12.511328 | controller | skipping: Conditional result was False
2025-12-01 09:04:12.545498 | 
2025-12-01 09:04:12.545586 | PLAY RECAP
2025-12-01 09:04:12.545640 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-01 09:04:12.545669 | 
2025-12-01 09:04:12.634065 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-01 09:04:12.634878 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-12-01 09:04:13.249688 | 
2025-12-01 09:04:13.249803 | PLAY [all]
2025-12-01 09:04:13.269442 | 
2025-12-01 09:04:13.269539 | TASK [include_role : fetch-output]
2025-12-01 09:04:13.319116 | controller | ok
2025-12-01 09:04:13.337218 | 
2025-12-01 09:04:13.337312 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-01 09:04:13.402153 | controller | skipping: Conditional result was False
2025-12-01 09:04:13.414592 | 
2025-12-01 09:04:13.415080 | TASK [fetch-output : Set log path for single node]
2025-12-01 09:04:13.470534 | controller | ok
2025-12-01 09:04:13.479233 | 
2025-12-01 09:04:13.480005 | LOOP [fetch-output : Ensure local output dirs]
2025-12-01 09:04:13.871143 | controller -> localhost | ok: "/var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/work/logs"
2025-12-01 09:04:14.112991 | controller -> localhost | changed: "/var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/work/artifacts"
2025-12-01 09:04:14.423932 | controller -> localhost | changed: "/var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/work/docs"
2025-12-01 09:04:14.440472 | 
2025-12-01 09:04:14.440586 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-01 09:04:15.077757 | controller | changed: .d..t...... ./
2025-12-01 09:04:15.078257 | controller | changed: All items complete
2025-12-01 09:04:15.078327 | 
2025-12-01 09:04:15.576919 | controller | changed: .d..t...... ./
2025-12-01 09:04:16.111934 | controller | changed: .d..t...... ./
2025-12-01 09:04:16.138184 | 
2025-12-01 09:04:16.138361 | TASK [include_role : fetch-output-openshift]
2025-12-01 09:04:16.165418 | controller | skipping: Conditional result was False
2025-12-01 09:04:16.176420 | 
2025-12-01 09:04:16.176585 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-12-01 09:04:16.650513 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.013204
2025-12-01 09:04:16.934670 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.014017
2025-12-01 09:04:16.964458 | 
2025-12-01 09:04:16.964575 | PLAY [all]
2025-12-01 09:04:16.979579 | 
2025-12-01 09:04:16.979721 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-12-01 09:04:17.467143 | controller | changed
2025-12-01 09:04:17.517101 | 
2025-12-01 09:04:17.517219 | PLAY RECAP
2025-12-01 09:04:17.517274 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-12-01 09:04:17.517303 | 
2025-12-01 09:04:17.649265 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-12-01 09:04:17.650184 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-12-01 09:04:18.274192 | 
2025-12-01 09:04:18.274307 | PLAY [localhost]
2025-12-01 09:04:18.292760 | 
2025-12-01 09:04:18.292875 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-12-01 09:04:18.711902 | localhost | changed
2025-12-01 09:04:18.722209 | 
2025-12-01 09:04:18.722376 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-12-01 09:04:18.759603 | localhost | ok
2025-12-01 09:04:18.778258 | 
2025-12-01 09:04:18.778553 | TASK [add-fileserver : Create SSH private key tempfile]
2025-12-01 09:04:19.131795 | localhost | changed
2025-12-01 09:04:19.143573 | 
2025-12-01 09:04:19.143721 | TASK [add-fileserver : Create SSH private key from secret]
2025-12-01 09:04:19.775591 | localhost | changed
2025-12-01 09:04:19.780737 | 
2025-12-01 09:04:19.780801 | TASK [add-fileserver : Add fileserver ssh key]
2025-12-01 09:04:20.215650 | localhost | Identity added: /var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/work/tmp/ansible.dzgxiie5 (/var/lib/zuul/builds/54854547eba84d6fb31b19119522424b/work/tmp/ansible.dzgxiie5)
2025-12-01 09:04:20.215837 | localhost | ok: Runtime: 0:00:00.012648
2025-12-01 09:04:20.220392 | 
2025-12-01 09:04:20.220454 | TASK [add-fileserver : Remove SSH private key from disk]
2025-12-01 09:04:20.502130 | localhost | ok: Runtime: 0:00:00.005555
2025-12-01 09:04:20.512710 | 
2025-12-01 09:04:20.512840 | TASK [add-fileserver : Add fileserver to inventory]
2025-12-01 09:04:20.570741 | localhost | changed
2025-12-01 09:04:20.580383 | 
2025-12-01 09:04:20.580536 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-12-01 09:04:20.946307 | localhost | changed
2025-12-01 09:04:20.987298 | 
2025-12-01 09:04:20.987392 | PLAY [localhost]
2025-12-01 09:04:21.004990 | 
2025-12-01 09:04:21.005119 | TASK [Generate bulk log download script]
2025-12-01 09:04:21.027681 | localhost | ok
2025-12-01 09:04:21.046219 | 
2025-12-01 09:04:21.046334 | TASK [local-log-download : Check API endpoint is defined]
2025-12-01 09:04:21.077401 | localhost | ok: All assertions passed
2025-12-01 09:04:21.084376 | 
2025-12-01 09:04:21.084471 | TASK [local-log-download : Create download script]
2025-12-01 09:04:21.574951 | localhost -> localhost | changed
2025-12-01 09:04:21.584095 | 
2025-12-01 09:04:21.584164 | TASK [Register quick-download link]
2025-12-01 09:04:21.601919 | localhost | ok
2025-12-01 09:04:21.642402 | 
2025-12-01 09:04:21.642506 | PLAY [logserver.rdoproject.org]
2025-12-01 09:04:21.652445 | 
2025-12-01 09:04:21.652506 | TASK [Set zuul-log-path fact]
2025-12-01 09:04:21.678870 | logserver.rdoproject.org | ok
2025-12-01 09:04:21.688203 | 
2025-12-01 09:04:21.688288 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-01 09:04:21.726251 | logserver.rdoproject.org | ok
2025-12-01 09:04:21.734411 | 
2025-12-01 09:04:21.734501 | TASK [upload-logs : Create log directories]
2025-12-01 09:04:22.594641 | logserver.rdoproject.org | changed
2025-12-01 09:04:22.602199 | 
2025-12-01 09:04:22.602333 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-12-01 09:04:22.955559 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.009122
2025-12-01 09:04:22.960309 | 
2025-12-01 09:04:22.960383 | TASK [upload-logs : Upload logs to log server]
2025-12-01 09:04:23.694872 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-12-01 09:04:23.701417 | 
2025-12-01 09:04:23.701557 | LOOP [upload-logs : Compress console log and json output]
2025-12-01 09:04:23.766777 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-01 09:04:23.775846 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-01 09:04:23.787540 | 
2025-12-01 09:04:23.787722 | LOOP [upload-logs : Upload compressed console log and json output]
2025-12-01 09:04:23.832876 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-01 09:04:23.833301 | 
2025-12-01 09:04:23.838100 | logserver.rdoproject.org | skipping: Conditional result was False
2025-12-01 09:04:23.853103 | 
2025-12-01 09:04:23.853287 | LOOP [upload-logs : Upload console log and json output]