2025-10-02 20:54:11.461966 | Job console starting...
2025-10-02 20:54:11.490411 | Updating repositories
2025-10-02 20:54:11.522966 | Preparing job workspace
2025-10-02 20:54:15.118346 | Running Ansible setup...
2025-10-02 20:54:19.049543 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-02 20:54:19.906282 | 
2025-10-02 20:54:19.906396 | PLAY [localhost]
2025-10-02 20:54:19.915038 | 
2025-10-02 20:54:19.915115 | TASK [Gathering Facts]
2025-10-02 20:54:21.213376 | localhost | ok
2025-10-02 20:54:21.233939 | 
2025-10-02 20:54:21.234121 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-02 20:54:21.727438 | localhost -> localhost | changed
2025-10-02 20:54:21.732966 | 
2025-10-02 20:54:21.733035 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-02 20:54:22.651984 | localhost -> localhost | changed
2025-10-02 20:54:22.661711 | 
2025-10-02 20:54:22.661843 | TASK [Setup log path fact]
2025-10-02 20:54:22.680293 | localhost | ok
2025-10-02 20:54:22.693327 | 
2025-10-02 20:54:22.693431 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-02 20:54:22.723301 | localhost | ok
2025-10-02 20:54:22.733830 | 
2025-10-02 20:54:22.733961 | TASK [emit-job-header : Print job information]
2025-10-02 20:54:22.762910 | # Job Information
2025-10-02 20:54:22.763129 | Ansible Version: 2.15.12
2025-10-02 20:54:22.763157 | Job: cifmw-molecule-krb_request
2025-10-02 20:54:22.763177 | Pipeline: github-check
2025-10-02 20:54:22.763196 | Executor: ze03.softwarefactory-project.io
2025-10-02 20:54:22.763214 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3362
2025-10-02 20:54:22.763232 | Log URL (when completed): https://logserver.rdoproject.org/32f/rdoproject.org/32f5fd5a58c341f9a8a95ecf6654581d/
2025-10-02 20:54:22.763250 | Event ID: b3260540-9fd1-11f0-99c1-8299ec1f8fbb
2025-10-02 20:54:22.767863 | 
2025-10-02 20:54:22.767945 | LOOP [emit-job-header : Print node information]
2025-10-02 20:54:22.890692 | localhost | ok:
2025-10-02 20:54:22.890894 | localhost | # Node Information
2025-10-02 20:54:22.890924 | localhost | Inventory Hostname: controller
2025-10-02 20:54:22.891230 | localhost | Hostname: np0005467400
2025-10-02 20:54:22.891265 | localhost | Username: zuul
2025-10-02 20:54:22.891287 | localhost | Distro: CentOS 9
2025-10-02 20:54:22.891306 | localhost | Provider: vexxhost-nodepool-tripleo
2025-10-02 20:54:22.891325 | localhost | Region: RegionOne
2025-10-02 20:54:22.891342 | localhost | Label: cloud-centos-9-stream-tripleo
2025-10-02 20:54:22.891359 | localhost | Product Name: OpenStack Nova
2025-10-02 20:54:22.891376 | localhost | Interface IP: 38.102.83.162
2025-10-02 20:54:22.912078 | 
2025-10-02 20:54:22.912184 | PLAY [all]
2025-10-02 20:54:22.918866 | 
2025-10-02 20:54:22.918943 | TASK [Gather network facts]
2025-10-02 20:54:23.453359 | controller | ok
2025-10-02 20:54:23.468931 | 
2025-10-02 20:54:23.469032 | TASK [include_role : start-zuul-console]
2025-10-02 20:54:23.488422 | controller | ok
2025-10-02 20:54:23.501497 | 
2025-10-02 20:54:23.501596 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-02 20:54:23.958961 | controller | ok
2025-10-02 20:54:23.968134 | 
2025-10-02 20:54:23.968238 | TASK [include_role : add-build-sshkey]
2025-10-02 20:54:23.989909 | controller | ok
2025-10-02 20:54:24.003598 | 
2025-10-02 20:54:24.003703 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-02 20:54:24.254165 | controller -> localhost | ok
2025-10-02 20:54:24.263526 | 
2025-10-02 20:54:24.263674 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-02 20:54:24.295218 | controller | ok
2025-10-02 20:54:24.309495 | controller | included: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-02 20:54:24.315555 | 
2025-10-02 20:54:24.315638 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-02 20:54:24.968061 | controller -> localhost | Generating public/private rsa key pair.
2025-10-02 20:54:24.968266 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/work/32f5fd5a58c341f9a8a95ecf6654581d_id_rsa.
2025-10-02 20:54:24.968298 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/work/32f5fd5a58c341f9a8a95ecf6654581d_id_rsa.pub.
2025-10-02 20:54:24.968321 | controller -> localhost | The key fingerprint is:
2025-10-02 20:54:24.968340 | controller -> localhost | SHA256:v6TYXww0jg3fV0J6u2PA/aPAOCVyKfJofEn4stDy+Oo zuul-build-sshkey
2025-10-02 20:54:24.968360 | controller -> localhost | The key's randomart image is:
2025-10-02 20:54:24.968378 | controller -> localhost | +---[RSA 3072]----+
2025-10-02 20:54:24.968396 | controller -> localhost | |              .  |
2025-10-02 20:54:24.968414 | controller -> localhost | |             o   |
2025-10-02 20:54:24.968432 | controller -> localhost | |        . o . o .|
2025-10-02 20:54:24.968450 | controller -> localhost | |      .  B.+ o + |
2025-10-02 20:54:24.968468 | controller -> localhost | |     o +S+=.+ +  |
2025-10-02 20:54:24.968485 | controller -> localhost | |    o * =.=o o o |
2025-10-02 20:54:24.968502 | controller -> localhost | |   o * = oooo +..|
2025-10-02 20:54:24.968519 | controller -> localhost | |    * +o o.o.....|
2025-10-02 20:54:24.968536 | controller -> localhost | |  .Eo+. o.o  .   |
2025-10-02 20:54:24.968553 | controller -> localhost | +----[SHA256]-----+
2025-10-02 20:54:24.968598 | controller -> localhost | ok: Runtime: 0:00:00.207682
2025-10-02 20:54:24.976740 | 
2025-10-02 20:54:24.976863 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-02 20:54:25.010850 | controller | ok
2025-10-02 20:54:25.020464 | controller | included: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-02 20:54:25.028561 | 
2025-10-02 20:54:25.028628 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-02 20:54:25.054518 | controller | skipping: Conditional result was False
2025-10-02 20:54:25.059931 | 
2025-10-02 20:54:25.059998 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-02 20:54:25.511553 | controller | changed
2025-10-02 20:54:25.531663 | 
2025-10-02 20:54:25.531791 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-02 20:54:25.749159 | controller | ok
2025-10-02 20:54:25.757189 | 
2025-10-02 20:54:25.757336 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-02 20:54:26.619860 | controller | changed
2025-10-02 20:54:26.627595 | 
2025-10-02 20:54:26.627716 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-02 20:54:27.569653 | controller | changed
2025-10-02 20:54:27.580221 | 
2025-10-02 20:54:27.580294 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-02 20:54:27.614480 | controller | skipping: Conditional result was False
2025-10-02 20:54:27.620140 | 
2025-10-02 20:54:27.620208 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-02 20:54:28.286048 | controller -> localhost | changed
2025-10-02 20:54:28.302079 | 
2025-10-02 20:54:28.302185 | TASK [add-build-sshkey : Add back temp key]
2025-10-02 20:54:28.553307 | controller -> localhost | Identity added: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/work/32f5fd5a58c341f9a8a95ecf6654581d_id_rsa (zuul-build-sshkey)
2025-10-02 20:54:28.553529 | controller -> localhost | ok: Runtime: 0:00:00.008914
2025-10-02 20:54:28.559850 | 
2025-10-02 20:54:28.559916 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-02 20:54:28.926413 | controller | ok
2025-10-02 20:54:28.933077 | 
2025-10-02 20:54:28.933160 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-02 20:54:28.967676 | controller | skipping: Conditional result was False
2025-10-02 20:54:28.981263 | 
2025-10-02 20:54:28.981373 | TASK [include_role : validate-host]
2025-10-02 20:54:29.015211 | controller | ok
2025-10-02 20:54:29.048661 | 
2025-10-02 20:54:29.048801 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-02 20:54:29.088124 | controller | ok
2025-10-02 20:54:29.099403 | 
2025-10-02 20:54:29.099535 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-02 20:54:29.412557 | controller -> localhost | ok
2025-10-02 20:54:29.419883 | 
2025-10-02 20:54:29.419970 | TASK [validate-host : Collect information about the host]
2025-10-02 20:54:30.274962 | controller | ok
2025-10-02 20:54:30.284015 | 
2025-10-02 20:54:30.284125 | TASK [validate-host : Sanitize hostname]
2025-10-02 20:54:30.397064 | controller | ok
2025-10-02 20:54:30.401968 | 
2025-10-02 20:54:30.402042 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-02 20:54:30.825000 | controller -> localhost | changed
2025-10-02 20:54:30.831622 | 
2025-10-02 20:54:30.831692 | TASK [validate-host : Collect information about zuul worker]
2025-10-02 20:54:31.320490 | controller | ok
2025-10-02 20:54:31.327991 | 
2025-10-02 20:54:31.328115 | TASK [validate-host : Write out all zuul information for each host]
2025-10-02 20:54:31.843326 | controller -> localhost | changed
2025-10-02 20:54:31.853210 | 
2025-10-02 20:54:31.853321 | TASK [include_role : prepare-workspace-openshift]
2025-10-02 20:54:31.877304 | controller | skipping: Conditional result was False
2025-10-02 20:54:31.882628 | 
2025-10-02 20:54:31.882714 | TASK [include_role : remove-zuul-sshkey]
2025-10-02 20:54:31.896719 | controller | skipping: Conditional result was False
2025-10-02 20:54:31.902896 | 
2025-10-02 20:54:31.903012 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-02 20:54:32.208579 | controller | ok: "logs"
2025-10-02 20:54:32.208829 | controller | ok: All items complete
2025-10-02 20:54:32.208858 | 
2025-10-02 20:54:32.481047 | controller | ok: "artifacts"
2025-10-02 20:54:32.744710 | controller | ok: "docs"
2025-10-02 20:54:32.757073 | 
2025-10-02 20:54:32.757191 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-02 20:54:33.070384 | controller | changed: "logs"
2025-10-02 20:54:33.325493 | controller | changed: "artifacts"
2025-10-02 20:54:33.588124 | controller | changed: "docs"
2025-10-02 20:54:33.619258 | 
2025-10-02 20:54:33.619376 | PLAY RECAP
2025-10-02 20:54:33.619420 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-02 20:54:33.619446 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-02 20:54:33.619465 | 
2025-10-02 20:54:33.725873 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-02 20:54:33.726708 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-02 20:54:34.381683 | 
2025-10-02 20:54:34.381845 | PLAY [localhost]
2025-10-02 20:54:34.399968 | 
2025-10-02 20:54:34.400099 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-10-02 20:54:34.822081 | localhost | ok
2025-10-02 20:54:34.831211 | 
2025-10-02 20:54:34.831360 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-10-02 20:54:35.536814 | localhost | changed
2025-10-02 20:54:35.557136 | 
2025-10-02 20:54:35.557267 | PLAY [all]
2025-10-02 20:54:35.572423 | 
2025-10-02 20:54:35.572528 | TASK [include_role : prepare-workspace]
2025-10-02 20:54:35.611477 | controller | ok
2025-10-02 20:54:35.625226 | 
2025-10-02 20:54:35.625301 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-02 20:54:36.104587 | controller | ok
2025-10-02 20:54:36.123072 | 
2025-10-02 20:54:36.123253 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-02 20:54:37.778418 | controller | Output suppressed because no_log was given
2025-10-02 20:54:37.791828 | 
2025-10-02 20:54:37.791906 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-02 20:54:38.075794 | controller | changed: "logs"
2025-10-02 20:54:38.318427 | controller | changed: "artifacts"
2025-10-02 20:54:38.560030 | controller | changed: "docs"
2025-10-02 20:54:38.576270 | 
2025-10-02 20:54:38.577013 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-02 20:54:38.917497 | controller | changed: "logs"
2025-10-02 20:54:38.917781 | controller | changed: All items complete
2025-10-02 20:54:38.917813 | 
2025-10-02 20:54:39.144073 | controller | changed: "artifacts"
2025-10-02 20:54:39.373335 | controller | changed: "docs"
2025-10-02 20:54:39.400834 | 
2025-10-02 20:54:39.400992 | TASK [Check if worker can sudo]
2025-10-02 20:54:39.948668 | controller | ok: Runtime: 0:00:00.064514
2025-10-02 20:54:39.954036 | 
2025-10-02 20:54:39.954102 | TASK [configure-mirrors : Gather needed facts]
2025-10-02 20:54:40.018558 | controller | skipping: Conditional result was False
2025-10-02 20:54:40.024428 | 
2025-10-02 20:54:40.024510 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-10-02 20:54:40.120279 | controller | ok
2025-10-02 20:54:40.138344 | controller | included: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-10-02 20:54:40.151002 | 
2025-10-02 20:54:40.151155 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-10-02 20:54:40.546638 | controller | ok
2025-10-02 20:54:40.554378 | 
2025-10-02 20:54:40.554467 | LOOP [configure-mirrors : Include OS-specific variables]
2025-10-02 20:54:40.659173 | controller | ok: "/var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-10-02 20:54:40.673846 | 
2025-10-02 20:54:40.673979 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-10-02 20:54:41.656901 | controller | changed
2025-10-02 20:54:41.664234 | 
2025-10-02 20:54:41.664343 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-10-02 20:54:41.760428 | controller | ok: "/var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-10-02 20:54:41.760632 | controller | ok: All items complete
2025-10-02 20:54:41.760658 | 
2025-10-02 20:54:41.845674 | controller | included: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-10-02 20:54:41.852442 | 
2025-10-02 20:54:41.852585 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-10-02 20:54:42.931126 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-10-02 20:54:43.854380 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-10-02 20:54:43.873789 | 
2025-10-02 20:54:43.873943 | TASK [configure-mirrors : Disable deltrarpm]
2025-10-02 20:54:44.349039 | controller | changed: section and option added
2025-10-02 20:54:44.367501 | 
2025-10-02 20:54:44.367568 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-10-02 20:54:45.237244 | controller | 29 files removed
2025-10-02 20:54:45.237512 | controller | ok: Item: dnf clean all Runtime: 0:00:00.545886
2025-10-02 20:54:45.237561 | controller | changed: All items complete
2025-10-02 20:54:45.237585 | 
2025-10-02 20:54:56.055848 | 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 20:54:56.055954 | controller | DNF version: 4.14.0
2025-10-02 20:54:56.055980 | controller | cachedir: /var/cache/dnf
2025-10-02 20:54:56.056000 | controller | Making cache files for all metadata files.
2025-10-02 20:54:56.056019 | controller | baseos: has expired and will be refreshed.
2025-10-02 20:54:56.056036 | controller | appstream: has expired and will be refreshed.
2025-10-02 20:54:56.056053 | controller | crb: has expired and will be refreshed.
2025-10-02 20:54:56.056078 | controller | extras-common: has expired and will be refreshed.
2025-10-02 20:54:56.056096 | controller | repo: downloading from remote: baseos
2025-10-02 20:54:56.056112 | controller | CentOS Stream 9 - BaseOS                         78 MB/s | 8.8 MB     00:00
2025-10-02 20:54:56.056128 | controller | baseos: using metadata from Tue 30 Sep 2025 01:12:56 PM EDT.
2025-10-02 20:54:56.056145 | controller | repo: downloading from remote: appstream
2025-10-02 20:54:56.056162 | controller | CentOS Stream 9 - AppStream                      93 MB/s |  25 MB     00:00
2025-10-02 20:54:56.056184 | controller | appstream: using metadata from Tue 30 Sep 2025 01:16:29 PM EDT.
2025-10-02 20:54:56.056206 | controller | repo: downloading from remote: crb
2025-10-02 20:54:56.056229 | controller | CentOS Stream 9 - CRB                            71 MB/s | 7.1 MB     00:00
2025-10-02 20:54:56.056247 | controller | crb: using metadata from Tue 30 Sep 2025 01:20:54 PM EDT.
2025-10-02 20:54:56.056264 | controller | repo: downloading from remote: extras-common
2025-10-02 20:54:56.056280 | controller | CentOS Stream 9 - Extras packages               1.5 MB/s |  20 kB     00:00
2025-10-02 20:54:56.056297 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT.
2025-10-02 20:54:56.056319 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-10-02 20:54:56.056342 | controller | Completion plugin: Generating completion cache...
2025-10-02 20:54:56.056365 | controller | Metadata cache created.
2025-10-02 20:54:56.056392 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.462262
2025-10-02 20:54:56.088198 | 
2025-10-02 20:54:56.088342 | PLAY RECAP
2025-10-02 20:54:56.088426 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-02 20:54:56.088484 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-02 20:54:56.088524 | 
2025-10-02 20:54:56.205584 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-02 20:54:56.207807 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-02 20:54:56.782286 | 
2025-10-02 20:54:56.782395 | PLAY [all]
2025-10-02 20:54:56.805494 | 
2025-10-02 20:54:56.805800 | TASK [Install binary dependencies]
2025-10-02 20:54:56.845057 | controller | ok
2025-10-02 20:54:56.863765 | 
2025-10-02 20:54:56.863850 | TASK [bindep : Include find tasks]
2025-10-02 20:54:56.892426 | controller | ok
2025-10-02 20:54:56.899917 | controller | included: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-02 20:54:56.905781 | 
2025-10-02 20:54:56.905842 | TASK [bindep : Look for bindep.txt]
2025-10-02 20:54:57.353853 | controller | ok
2025-10-02 20:54:57.367249 | 
2025-10-02 20:54:57.367409 | TASK [bindep : Define bindep_file fact]
2025-10-02 20:54:57.415574 | controller | ok
2025-10-02 20:54:57.429115 | 
2025-10-02 20:54:57.429301 | TASK [bindep : Look for other-requirements.txt]
2025-10-02 20:54:57.456353 | controller | skipping: Conditional result was False
2025-10-02 20:54:57.464477 | 
2025-10-02 20:54:57.464586 | TASK [bindep : Define bindep_file fact]
2025-10-02 20:54:57.499941 | controller | skipping: Conditional result was False
2025-10-02 20:54:57.508214 | 
2025-10-02 20:54:57.508319 | TASK [bindep : Look for bindep fallback file]
2025-10-02 20:54:57.544090 | controller | skipping: Conditional result was False
2025-10-02 20:54:57.552904 | 
2025-10-02 20:54:57.553069 | TASK [bindep : Define bindep_file fact]
2025-10-02 20:54:57.578277 | controller | skipping: Conditional result was False
2025-10-02 20:54:57.587037 | 
2025-10-02 20:54:57.587139 | TASK [bindep : Include bindep tasks]
2025-10-02 20:54:57.630459 | controller | ok
2025-10-02 20:54:57.639286 | controller | included: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-10-02 20:54:57.649835 | 
2025-10-02 20:54:57.649912 | TASK [bindep : Look for bindep command]
2025-10-02 20:54:57.684188 | controller | skipping: Conditional result was False
2025-10-02 20:54:57.690441 | 
2025-10-02 20:54:57.690517 | TASK [bindep : Check for system bindep]
2025-10-02 20:54:58.220209 | controller | ok: Runtime: 0:00:00.009536
2025-10-02 20:54:58.227953 | 
2025-10-02 20:54:58.228055 | TASK [bindep : Define bindep_command fact]
2025-10-02 20:54:58.263986 | controller | skipping: Conditional result was False
2025-10-02 20:54:58.271979 | 
2025-10-02 20:54:58.272125 | TASK [bindep : Include install tasks]
2025-10-02 20:54:58.315496 | controller | ok
2025-10-02 20:54:58.325535 | controller | included: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-10-02 20:54:58.338125 | 
2025-10-02 20:54:58.338230 | TASK [bindep : Create temp dir for bindep]
2025-10-02 20:54:58.761379 | controller | changed
2025-10-02 20:54:58.773135 | 
2025-10-02 20:54:58.773266 | TASK [Ensure we have pip dependencies]
2025-10-02 20:54:58.800217 | controller | ok
2025-10-02 20:54:58.841154 | 
2025-10-02 20:54:58.841290 | TASK [ensure-pip : Check if pip is installed]
2025-10-02 16:54:59.166099 | controller | /usr/bin/pip3
2025-10-02 16:54:59.210219 | controller | /usr/bin/python3: No module named wheel
2025-10-02 20:54:59.377068 | controller | ok: Runtime: 0:00:00.061235
2025-10-02 20:54:59.389519 | 
2025-10-02 20:54:59.389668 | LOOP [ensure-pip : Install pip from packages]
2025-10-02 20:54:59.422235 | controller | ok: "/var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-10-02 20:54:59.443557 | controller | included: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-10-02 20:54:59.466154 | 
2025-10-02 20:54:59.466292 | TASK [ensure-pip : Install Python 3 pip]
2025-10-02 20:55:02.033669 | controller | changed
2025-10-02 20:55:02.045179 | 
2025-10-02 20:55:02.045344 | TASK [ensure-pip : Check for EPEL repository]
2025-10-02 20:55:02.113350 | controller | skipping: Conditional result was False
2025-10-02 20:55:02.127056 | 
2025-10-02 20:55:02.127241 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-10-02 20:55:02.185391 | controller | skipping: Conditional result was False
2025-10-02 20:55:02.200176 | 
2025-10-02 20:55:02.200409 | TASK [ensure-pip : Install Python 2 pip]
2025-10-02 20:55:02.247688 | controller | skipping: Conditional result was False
2025-10-02 20:55:02.263365 | 
2025-10-02 20:55:02.263542 | TASK [ensure-pip : Ensure setuptools]
2025-10-02 20:55:02.282007 | controller | skipping: Conditional result was False
2025-10-02 20:55:02.295854 | 
2025-10-02 20:55:02.296005 | TASK [ensure-pip : Check for ensurepip module]
2025-10-02 20:55:02.842307 | controller | skipping: Conditional result was False
2025-10-02 20:55:02.855314 | 
2025-10-02 20:55:02.855464 | TASK [ensure-pip : Ensure python3-venv]
2025-10-02 20:55:02.882235 | controller | skipping: Conditional result was False
2025-10-02 20:55:02.895157 | 
2025-10-02 20:55:02.895303 | TASK [ensure-pip : Install pip from source]
2025-10-02 20:55:02.922041 | controller | skipping: Conditional result was False
2025-10-02 20:55:02.934080 | 
2025-10-02 20:55:02.934147 | TASK [ensure-pip : Probe for venv python full path]
2025-10-02 16:55:03.282808 | controller | /usr/bin/python3
2025-10-02 20:55:03.464594 | controller | ok: Runtime: 0:00:00.011599
2025-10-02 20:55:03.477216 | 
2025-10-02 20:55:03.477358 | TASK [ensure-pip : Set host default]
2025-10-02 20:55:03.536693 | controller | ok
2025-10-02 20:55:03.548876 | 
2025-10-02 20:55:03.549019 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-10-02 20:55:03.641349 | controller | ok
2025-10-02 20:55:03.663964 | 
2025-10-02 20:55:03.664109 | TASK [bindep : Install bindep into temporary venv]
2025-10-02 20:55:07.955829 | controller | changed
2025-10-02 20:55:07.968890 | 
2025-10-02 20:55:07.969090 | TASK [bindep : Define bindep_command]
2025-10-02 20:55:08.009890 | controller | ok
2025-10-02 20:55:08.022254 | 
2025-10-02 20:55:08.022444 | LOOP [bindep : Include package tasks]
2025-10-02 20:55:08.103847 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-10-02 20:55:08.104475 | controller | ok: All items complete
2025-10-02 20:55:08.104539 | 
2025-10-02 20:55:08.132776 | controller | included: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-10-02 20:55:08.160476 | 
2025-10-02 20:55:08.160666 | TASK [bindep : Define bindep_run fact]
2025-10-02 20:55:08.194383 | controller | ok
2025-10-02 20:55:08.204008 | 
2025-10-02 20:55:08.204179 | TASK [bindep : Get list of packages to install from bindep]
2025-10-02 16:55:09.700194 | controller | podman
2025-10-02 16:55:09.741196 | controller | python3-jmespath
2025-10-02 16:55:09.741402 | controller | python3-libvirt
2025-10-02 16:55:09.741418 | controller | python3-lxml
2025-10-02 16:55:09.741427 | controller | python3-netaddr
2025-10-02 20:55:09.784067 | controller | ok: Runtime: 0:00:01.199989
2025-10-02 20:55:09.792538 | 
2025-10-02 20:55:09.792630 | TASK [bindep : Install distro packages from bindep]
2025-10-02 20:56:12.047274 | controller | changed
2025-10-02 20:56:12.057595 | 
2025-10-02 20:56:12.057716 | TASK [bindep : Check that packages are installed]
2025-10-02 20:56:14.149106 | controller | ok: Runtime: 0:00:01.310935
2025-10-02 20:56:14.163532 | 
2025-10-02 20:56:14.163705 | TASK [bindep : Fail if we cannot install all packages]
2025-10-02 20:56:14.191420 | controller | skipping: Conditional result was False
2025-10-02 20:56:14.217051 | 
2025-10-02 20:56:14.217251 | TASK [Run test-setup role]
2025-10-02 20:56:14.241549 | controller | ok
2025-10-02 20:56:14.269254 | 
2025-10-02 20:56:14.269416 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-02 20:56:14.552616 | controller | ok
2025-10-02 20:56:14.575077 | 
2025-10-02 20:56:14.575276 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-02 20:56:14.629075 | controller | skipping: Conditional result was False
2025-10-02 20:56:14.658137 | 
2025-10-02 20:56:14.658308 | TASK [bindep : Remove bindep temp dir]
2025-10-02 20:56:15.076220 | controller | ok
2025-10-02 20:56:15.088949 | 
2025-10-02 20:56:15.089084 | PLAY RECAP
2025-10-02 20:56:15.089126 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-10-02 20:56:15.089185 | 
2025-10-02 20:56:15.212016 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-02 20:56:15.213077 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-02 20:56:15.890373 | 
2025-10-02 20:56:15.890520 | PLAY [all]
2025-10-02 20:56:15.911161 | 
2025-10-02 20:56:15.911309 | TASK [Abort when test_command variable is undefined]
2025-10-02 20:56:15.950589 | controller | skipping: Conditional result was False
2025-10-02 20:56:15.956385 | 
2025-10-02 20:56:15.956478 | TASK [Convert test_command to list]
2025-10-02 20:56:16.001003 | controller | skipping: Conditional result was False
2025-10-02 20:56:16.007367 | 
2025-10-02 20:56:16.007477 | TASK [Use test_command list]
2025-10-02 20:56:16.056881 | controller | ok
2025-10-02 20:56:16.062196 | 
2025-10-02 20:56:16.062258 | LOOP [Run test_command]
2025-10-02 20:56:16.473476 | controller | no check to run
2025-10-02 20:56:16.473872 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.009168
2025-10-02 20:56:16.527682 | 
2025-10-02 20:56:16.527898 | PLAY RECAP
2025-10-02 20:56:16.527965 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-02 20:56:16.527995 | 
2025-10-02 20:56:16.635408 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-02 20:56:16.637398 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-02 20:56:17.188943 | 
2025-10-02 20:56:17.189080 | PLAY [all]
2025-10-02 20:56:17.210063 | 
2025-10-02 20:56:17.210192 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-02 20:56:17.686531 | controller | changed: non-zero return code
2025-10-02 20:56:17.700474 | 
2025-10-02 20:56:17.700682 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-02 20:56:17.717470 | controller | skipping: Conditional result was False
2025-10-02 20:56:17.730015 | 
2025-10-02 20:56:17.730210 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-02 20:56:17.770048 | 
2025-10-02 20:56:17.770331 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-02 20:56:17.808329 | 
2025-10-02 20:56:17.808624 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-02 20:56:17.825363 | controller | skipping: Conditional result was False
2025-10-02 20:56:17.839373 | 
2025-10-02 20:56:17.839566 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-02 20:56:17.879635 | 
2025-10-02 20:56:17.880008 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-02 20:56:17.895815 | controller | skipping: Conditional result was False
2025-10-02 20:56:17.907646 | 
2025-10-02 20:56:17.907820 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-02 20:56:17.923356 | controller | skipping: Conditional result was False
2025-10-02 20:56:17.935203 | 
2025-10-02 20:56:17.935373 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-02 20:56:17.951420 | controller | skipping: Conditional result was False
2025-10-02 20:56:17.996436 | 
2025-10-02 20:56:17.996564 | PLAY RECAP
2025-10-02 20:56:17.996625 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-02 20:56:17.996655 | 
2025-10-02 20:56:18.097697 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-02 20:56:18.098552 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-02 20:56:18.734349 | 
2025-10-02 20:56:18.734477 | PLAY [all]
2025-10-02 20:56:18.754323 | 
2025-10-02 20:56:18.754456 | TASK [include_role : fetch-output]
2025-10-02 20:56:18.784958 | controller | ok
2025-10-02 20:56:18.804186 | 
2025-10-02 20:56:18.804329 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-02 20:56:18.851431 | controller | skipping: Conditional result was False
2025-10-02 20:56:18.861710 | 
2025-10-02 20:56:18.861876 | TASK [fetch-output : Set log path for single node]
2025-10-02 20:56:18.895801 | controller | ok
2025-10-02 20:56:18.904784 | 
2025-10-02 20:56:18.904960 | LOOP [fetch-output : Ensure local output dirs]
2025-10-02 20:56:19.312259 | controller -> localhost | ok: "/var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/work/logs"
2025-10-02 20:56:19.571782 | controller -> localhost | changed: "/var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/work/artifacts"
2025-10-02 20:56:19.808436 | controller -> localhost | changed: "/var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/work/docs"
2025-10-02 20:56:19.826653 | 
2025-10-02 20:56:19.826878 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-02 20:56:20.562597 | controller | changed: .d..t...... ./
2025-10-02 20:56:20.562989 | controller | changed: All items complete
2025-10-02 20:56:20.563049 | 
2025-10-02 20:56:21.139952 | controller | changed: .d..t...... ./
2025-10-02 20:56:21.711993 | controller | changed: .d..t...... ./
2025-10-02 20:56:21.724834 | 
2025-10-02 20:56:21.724964 | TASK [include_role : fetch-output-openshift]
2025-10-02 20:56:21.748911 | controller | skipping: Conditional result was False
2025-10-02 20:56:21.755924 | 
2025-10-02 20:56:21.756019 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-02 20:56:22.204866 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.013068
2025-10-02 20:56:22.442919 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.013475
2025-10-02 20:56:22.475911 | 
2025-10-02 20:56:22.476022 | PLAY [all]
2025-10-02 20:56:22.491128 | 
2025-10-02 20:56:22.491249 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-02 20:56:23.010978 | controller | changed
2025-10-02 20:56:23.040082 | 
2025-10-02 20:56:23.040214 | PLAY RECAP
2025-10-02 20:56:23.040271 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-02 20:56:23.040299 | 
2025-10-02 20:56:23.149635 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-02 20:56:23.150532 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-02 20:56:23.800955 | 
2025-10-02 20:56:23.801136 | PLAY [localhost]
2025-10-02 20:56:23.820369 | 
2025-10-02 20:56:23.820510 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-02 20:56:24.224823 | localhost | changed
2025-10-02 20:56:24.235285 | 
2025-10-02 20:56:24.235458 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-02 20:56:24.272020 | localhost | ok
2025-10-02 20:56:24.288975 | 
2025-10-02 20:56:24.289133 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-02 20:56:24.658417 | localhost | changed
2025-10-02 20:56:24.667210 | 
2025-10-02 20:56:24.667358 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-02 20:56:25.281067 | localhost | changed
2025-10-02 20:56:25.286249 | 
2025-10-02 20:56:25.286323 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-02 20:56:25.701800 | localhost | Identity added: /var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/work/tmp/ansible.t68yg19n (/var/lib/zuul/builds/32f5fd5a58c341f9a8a95ecf6654581d/work/tmp/ansible.t68yg19n)
2025-10-02 20:56:25.701990 | localhost | ok: Runtime: 0:00:00.014363
2025-10-02 20:56:25.707228 | 
2025-10-02 20:56:25.707310 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-02 20:56:26.019717 | localhost | ok: Runtime: 0:00:00.008344
2025-10-02 20:56:26.030032 | 
2025-10-02 20:56:26.030159 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-02 20:56:26.089594 | localhost | changed
2025-10-02 20:56:26.099625 | 
2025-10-02 20:56:26.099801 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-02 20:56:26.512634 | localhost | changed
2025-10-02 20:56:26.550572 | 
2025-10-02 20:56:26.550744 | PLAY [localhost]
2025-10-02 20:56:26.566704 | 
2025-10-02 20:56:26.566805 | TASK [Generate bulk log download script]
2025-10-02 20:56:26.598328 | localhost | ok
2025-10-02 20:56:26.615390 | 
2025-10-02 20:56:26.615505 | TASK [local-log-download : Check API endpoint is defined]
2025-10-02 20:56:26.656523 | localhost | ok: All assertions passed
2025-10-02 20:56:26.662995 | 
2025-10-02 20:56:26.663109 | TASK [local-log-download : Create download script]
2025-10-02 20:56:27.149876 | localhost -> localhost | changed
2025-10-02 20:56:27.173995 | 
2025-10-02 20:56:27.174131 | TASK [Register quick-download link]
2025-10-02 20:56:27.203854 | localhost | ok
2025-10-02 20:56:27.252951 | 
2025-10-02 20:56:27.253058 | PLAY [logserver.rdoproject.org]
2025-10-02 20:56:27.262371 | 
2025-10-02 20:56:27.262439 | TASK [Set zuul-log-path fact]
2025-10-02 20:56:27.279006 | logserver.rdoproject.org | ok
2025-10-02 20:56:27.288244 | 
2025-10-02 20:56:27.288318 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-02 20:56:27.324880 | logserver.rdoproject.org | ok
2025-10-02 20:56:27.330316 | 
2025-10-02 20:56:27.330378 | TASK [upload-logs : Create log directories]
2025-10-02 20:56:28.103382 | logserver.rdoproject.org | changed
2025-10-02 20:56:28.110357 | 
2025-10-02 20:56:28.110487 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-02 20:56:28.463469 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.010422
2025-10-02 20:56:28.471301 | 
2025-10-02 20:56:28.471451 | TASK [upload-logs : Upload logs to log server]
2025-10-02 20:56:29.199927 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-02 20:56:29.207883 | 
2025-10-02 20:56:29.208036 | LOOP [upload-logs : Compress console log and json output]
2025-10-02 20:56:29.280083 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 20:56:29.304092 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 20:56:29.315306 | 
2025-10-02 20:56:29.315521 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-02 20:56:29.361642 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 20:56:29.361966 | 
2025-10-02 20:56:29.368375 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-02 20:56:29.383059 | 
2025-10-02 20:56:29.383298 | LOOP [upload-logs : Upload console log and json output]