2025-10-13 13:27:36.721270 | Job console starting...
2025-10-13 13:27:36.730007 | Updating repositories
2025-10-13 13:27:36.797212 | Preparing job workspace
2025-10-13 13:27:46.090303 | Running Ansible setup...
2025-10-13 13:27:50.110155 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-13 13:27:50.936779 | 
2025-10-13 13:27:50.936889 | PLAY [localhost]
2025-10-13 13:27:50.948743 | 
2025-10-13 13:27:50.948823 | TASK [Gathering Facts]
2025-10-13 13:27:52.246992 | localhost | ok
2025-10-13 13:27:52.261556 | 
2025-10-13 13:27:52.261646 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-13 13:27:52.826055 | localhost -> localhost | changed
2025-10-13 13:27:52.831411 | 
2025-10-13 13:27:52.831478 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-13 13:27:53.866372 | localhost -> localhost | changed
2025-10-13 13:27:53.875891 | 
2025-10-13 13:27:53.875962 | TASK [Setup log path fact]
2025-10-13 13:27:53.912094 | localhost | ok
2025-10-13 13:27:53.942136 | 
2025-10-13 13:27:53.942242 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 13:27:53.996652 | localhost | ok
2025-10-13 13:27:54.005412 | 
2025-10-13 13:27:54.005507 | TASK [emit-job-header : Print job information]
2025-10-13 13:27:54.062642 | # Job Information
2025-10-13 13:27:54.062892 | Ansible Version: 2.15.12
2025-10-13 13:27:54.062919 | Job: cifmw-molecule-krb_request
2025-10-13 13:27:54.062939 | Pipeline: github-check
2025-10-13 13:27:54.062958 | Executor: ze02.softwarefactory-project.io
2025-10-13 13:27:54.062975 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3402
2025-10-13 13:27:54.062994 | Log URL (when completed): https://logserver.rdoproject.org/007/rdoproject.org/007ac2ac5cf04d858f37ae2d67e9e605/
2025-10-13 13:27:54.063012 | Event ID: 1d8d4d80-a838-11f0-8dac-98223402f22d
2025-10-13 13:27:54.066643 | 
2025-10-13 13:27:54.066736 | LOOP [emit-job-header : Print node information]
2025-10-13 13:27:54.232734 | localhost | ok:
2025-10-13 13:27:54.232946 | localhost | # Node Information
2025-10-13 13:27:54.232977 | localhost | Inventory Hostname: controller
2025-10-13 13:27:54.233000 | localhost | Hostname: np0005484799
2025-10-13 13:27:54.233020 | localhost | Username: zuul
2025-10-13 13:27:54.233040 | localhost | Distro: CentOS 9
2025-10-13 13:27:54.233059 | localhost | Provider: vexxhost-nodepool-tripleo
2025-10-13 13:27:54.233077 | localhost | Region: RegionOne
2025-10-13 13:27:54.233094 | localhost | Label: cloud-centos-9-stream-tripleo
2025-10-13 13:27:54.233111 | localhost | Product Name: OpenStack Nova
2025-10-13 13:27:54.233127 | localhost | Interface IP: 38.129.56.146
2025-10-13 13:27:54.278074 | 
2025-10-13 13:27:54.278157 | PLAY [all]
2025-10-13 13:27:54.288929 | 
2025-10-13 13:27:54.288992 | TASK [Gather network facts]
2025-10-13 13:27:54.845613 | controller | ok
2025-10-13 13:27:54.876268 | 
2025-10-13 13:27:54.876348 | TASK [include_role : start-zuul-console]
2025-10-13 13:27:54.928333 | controller | ok
2025-10-13 13:27:54.947565 | 
2025-10-13 13:27:54.947640 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-13 13:27:55.410391 | controller | ok
2025-10-13 13:27:55.425230 | 
2025-10-13 13:27:55.425336 | TASK [include_role : add-build-sshkey]
2025-10-13 13:27:55.480867 | controller | ok
2025-10-13 13:27:55.513249 | 
2025-10-13 13:27:55.513357 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-13 13:27:55.798570 | controller -> localhost | ok
2025-10-13 13:27:55.804976 | 
2025-10-13 13:27:55.805050 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-13 13:27:55.844173 | controller | ok
2025-10-13 13:27:55.858492 | controller | included: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-13 13:27:55.864559 | 
2025-10-13 13:27:55.864626 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-13 13:27:56.508444 | controller -> localhost | Generating public/private rsa key pair.
2025-10-13 13:27:56.508638 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/work/007ac2ac5cf04d858f37ae2d67e9e605_id_rsa.
2025-10-13 13:27:56.508683 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/work/007ac2ac5cf04d858f37ae2d67e9e605_id_rsa.pub.
2025-10-13 13:27:56.508710 | controller -> localhost | The key fingerprint is:
2025-10-13 13:27:56.508730 | controller -> localhost | SHA256:EA68SrimCSnZwpRdfGvLnJ51d3/cc47JL1/xmVqLxnk zuul-build-sshkey
2025-10-13 13:27:56.508749 | controller -> localhost | The key's randomart image is:
2025-10-13 13:27:56.508767 | controller -> localhost | +---[RSA 3072]----+
2025-10-13 13:27:56.508784 | controller -> localhost | |   .o .          |
2025-10-13 13:27:56.508802 | controller -> localhost | |    .= o         |
2025-10-13 13:27:56.508820 | controller -> localhost | | .o ..+ .        |
2025-10-13 13:27:56.508838 | controller -> localhost | |.o...  +         |
2025-10-13 13:27:56.508855 | controller -> localhost | |o* .  + S      . |
2025-10-13 13:27:56.508872 | controller -> localhost | |Boo    = . . . .=|
2025-10-13 13:27:56.508890 | controller -> localhost | |=o    . o . o o==|
2025-10-13 13:27:56.508914 | controller -> localhost | |o      o     ==EO|
2025-10-13 13:27:56.508931 | controller -> localhost | |            .o=*B|
2025-10-13 13:27:56.508948 | controller -> localhost | +----[SHA256]-----+
2025-10-13 13:27:56.508989 | controller -> localhost | ok: Runtime: 0:00:00.246975
2025-10-13 13:27:56.514556 | 
2025-10-13 13:27:56.514616 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-13 13:27:56.533024 | controller | ok
2025-10-13 13:27:56.543408 | controller | included: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-13 13:27:56.551131 | 
2025-10-13 13:27:56.551193 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-13 13:27:56.575150 | controller | skipping: Conditional result was False
2025-10-13 13:27:56.580501 | 
2025-10-13 13:27:56.580562 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-13 13:27:57.113740 | controller | changed
2025-10-13 13:27:57.126838 | 
2025-10-13 13:27:57.127037 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-13 13:27:57.423627 | controller | ok
2025-10-13 13:27:57.429363 | 
2025-10-13 13:27:57.429436 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-13 13:27:58.349800 | controller | changed
2025-10-13 13:27:58.359069 | 
2025-10-13 13:27:58.359162 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-13 13:27:59.232469 | controller | changed
2025-10-13 13:27:59.237856 | 
2025-10-13 13:27:59.237917 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-13 13:27:59.261827 | controller | skipping: Conditional result was False
2025-10-13 13:27:59.267359 | 
2025-10-13 13:27:59.267422 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-13 13:27:59.640513 | controller -> localhost | changed
2025-10-13 13:27:59.651554 | 
2025-10-13 13:27:59.651688 | TASK [add-build-sshkey : Add back temp key]
2025-10-13 13:27:59.912688 | controller -> localhost | Identity added: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/work/007ac2ac5cf04d858f37ae2d67e9e605_id_rsa (zuul-build-sshkey)
2025-10-13 13:27:59.912890 | controller -> localhost | ok: Runtime: 0:00:00.008784
2025-10-13 13:27:59.924903 | 
2025-10-13 13:27:59.925024 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-13 13:28:00.274986 | controller | ok
2025-10-13 13:28:00.281507 | 
2025-10-13 13:28:00.281599 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-13 13:28:00.307706 | controller | skipping: Conditional result was False
2025-10-13 13:28:00.320087 | 
2025-10-13 13:28:00.320174 | TASK [include_role : validate-host]
2025-10-13 13:28:00.351365 | controller | ok
2025-10-13 13:28:00.394845 | 
2025-10-13 13:28:00.394970 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-13 13:28:00.423986 | controller | ok
2025-10-13 13:28:00.428687 | 
2025-10-13 13:28:00.428747 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-13 13:28:00.721115 | controller -> localhost | ok
2025-10-13 13:28:00.759307 | 
2025-10-13 13:28:00.759430 | TASK [validate-host : Collect information about the host]
2025-10-13 13:28:01.524284 | controller | ok
2025-10-13 13:28:01.535125 | 
2025-10-13 13:28:01.535198 | TASK [validate-host : Sanitize hostname]
2025-10-13 13:28:01.617588 | controller | ok
2025-10-13 13:28:01.622660 | 
2025-10-13 13:28:01.622746 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-13 13:28:02.097302 | controller -> localhost | changed
2025-10-13 13:28:02.104520 | 
2025-10-13 13:28:02.104712 | TASK [validate-host : Collect information about zuul worker]
2025-10-13 13:28:02.528740 | controller | ok
2025-10-13 13:28:02.533556 | 
2025-10-13 13:28:02.533619 | TASK [validate-host : Write out all zuul information for each host]
2025-10-13 13:28:03.261388 | controller -> localhost | changed
2025-10-13 13:28:03.273388 | 
2025-10-13 13:28:03.273507 | TASK [include_role : prepare-workspace-openshift]
2025-10-13 13:28:03.329339 | controller | skipping: Conditional result was False
2025-10-13 13:28:03.334621 | 
2025-10-13 13:28:03.334698 | TASK [include_role : remove-zuul-sshkey]
2025-10-13 13:28:03.380046 | controller | skipping: Conditional result was False
2025-10-13 13:28:03.385545 | 
2025-10-13 13:28:03.385608 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-13 13:28:03.640731 | controller | ok: "logs"
2025-10-13 13:28:03.640977 | controller | ok: All items complete
2025-10-13 13:28:03.641006 | 
2025-10-13 13:28:03.883335 | controller | ok: "artifacts"
2025-10-13 13:28:04.136416 | controller | ok: "docs"
2025-10-13 13:28:04.150731 | 
2025-10-13 13:28:04.150858 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-13 13:28:04.400586 | controller | changed: "logs"
2025-10-13 13:28:04.650082 | controller | changed: "artifacts"
2025-10-13 13:28:04.900487 | controller | changed: "docs"
2025-10-13 13:28:04.952823 | 
2025-10-13 13:28:04.952921 | PLAY RECAP
2025-10-13 13:28:04.952965 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-13 13:28:04.952990 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-13 13:28:04.953007 | 
2025-10-13 13:28:05.195100 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-13 13:28:05.195931 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-13 13:28:05.870521 | 
2025-10-13 13:28:05.870633 | PLAY [localhost]
2025-10-13 13:28:05.886985 | 
2025-10-13 13:28:05.887058 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-10-13 13:28:06.305800 | localhost | ok
2025-10-13 13:28:06.311876 | 
2025-10-13 13:28:06.311961 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-10-13 13:28:07.453598 | localhost | changed
2025-10-13 13:28:07.473104 | 
2025-10-13 13:28:07.473160 | PLAY [all]
2025-10-13 13:28:07.488889 | 
2025-10-13 13:28:07.488951 | TASK [include_role : prepare-workspace]
2025-10-13 13:28:07.511187 | controller | ok
2025-10-13 13:28:07.533491 | 
2025-10-13 13:28:07.533567 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-13 13:28:07.917011 | controller | ok
2025-10-13 13:28:07.926109 | 
2025-10-13 13:28:07.926195 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-13 13:28:09.938419 | controller | Output suppressed because no_log was given
2025-10-13 13:28:09.957421 | 
2025-10-13 13:28:09.957520 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-13 13:28:10.234160 | controller | changed: "logs"
2025-10-13 13:28:10.418561 | controller | changed: "artifacts"
2025-10-13 13:28:10.633613 | controller | changed: "docs"
2025-10-13 13:28:10.643977 | 
2025-10-13 13:28:10.644101 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-13 13:28:10.905125 | controller | changed: "logs"
2025-10-13 13:28:10.905358 | controller | changed: All items complete
2025-10-13 13:28:10.905385 | 
2025-10-13 13:28:11.132495 | controller | changed: "artifacts"
2025-10-13 13:28:11.350187 | controller | changed: "docs"
2025-10-13 13:28:11.370613 | 
2025-10-13 13:28:11.370745 | TASK [Check if worker can sudo]
2025-10-13 13:28:11.900994 | controller | ok: Runtime: 0:00:00.046796
2025-10-13 13:28:11.914904 | 
2025-10-13 13:28:11.915039 | TASK [configure-mirrors : Gather needed facts]
2025-10-13 13:28:11.979920 | controller | skipping: Conditional result was False
2025-10-13 13:28:11.985920 | 
2025-10-13 13:28:11.985985 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-10-13 13:28:12.048712 | controller | ok
2025-10-13 13:28:12.064090 | controller | included: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-10-13 13:28:12.096064 | 
2025-10-13 13:28:12.096198 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-10-13 13:28:12.401843 | controller | ok
2025-10-13 13:28:12.422842 | 
2025-10-13 13:28:12.423002 | LOOP [configure-mirrors : Include OS-specific variables]
2025-10-13 13:28:12.500288 | controller | ok: "/var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-10-13 13:28:12.518570 | 
2025-10-13 13:28:12.518696 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-10-13 13:28:13.324445 | controller | changed
2025-10-13 13:28:13.331520 | 
2025-10-13 13:28:13.331580 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-10-13 13:28:13.386727 | controller | ok: "/var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-10-13 13:28:13.389157 | controller | ok: All items complete
2025-10-13 13:28:13.389248 | 
2025-10-13 13:28:13.436282 | controller | included: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-10-13 13:28:13.442651 | 
2025-10-13 13:28:13.442730 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-10-13 13:28:14.540618 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-10-13 13:28:15.418443 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-10-13 13:28:15.431569 | 
2025-10-13 13:28:15.431871 | TASK [configure-mirrors : Disable deltrarpm]
2025-10-13 13:28:15.854618 | controller | changed: section and option added
2025-10-13 13:28:15.888365 | 
2025-10-13 13:28:15.888461 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-10-13 13:28:16.734692 | controller | 29 files removed
2025-10-13 13:28:16.735070 | controller | ok: Item: dnf clean all Runtime: 0:00:00.512736
2025-10-13 13:28:16.735149 | controller | changed: All items complete
2025-10-13 13:28:16.735193 | 
2025-10-13 13:28:27.839496 | 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 13:28:27.839656 | controller | DNF version: 4.14.0
2025-10-13 13:28:27.839747 | controller | cachedir: /var/cache/dnf
2025-10-13 13:28:27.840476 | controller | Making cache files for all metadata files.
2025-10-13 13:28:27.840545 | controller | baseos: has expired and will be refreshed.
2025-10-13 13:28:27.840588 | controller | appstream: has expired and will be refreshed.
2025-10-13 13:28:27.840625 | controller | crb: has expired and will be refreshed.
2025-10-13 13:28:27.840705 | controller | extras-common: has expired and will be refreshed.
2025-10-13 13:28:27.840755 | controller | repo: downloading from remote: baseos
2025-10-13 13:28:27.840793 | controller | CentOS Stream 9 - BaseOS                         60 MB/s | 8.8 MB     00:00
2025-10-13 13:28:27.840828 | controller | baseos: using metadata from Wed 08 Oct 2025 09:42:12 AM EDT.
2025-10-13 13:28:27.840864 | controller | repo: downloading from remote: appstream
2025-10-13 13:28:27.840899 | controller | CentOS Stream 9 - AppStream                      82 MB/s |  25 MB     00:00
2025-10-13 13:28:27.840934 | controller | appstream: using metadata from Wed 08 Oct 2025 09:45:45 AM EDT.
2025-10-13 13:28:27.840968 | controller | repo: downloading from remote: crb
2025-10-13 13:28:27.841002 | controller | CentOS Stream 9 - CRB                            57 MB/s | 7.2 MB     00:00
2025-10-13 13:28:27.841038 | controller | crb: using metadata from Wed 08 Oct 2025 09:50:07 AM EDT.
2025-10-13 13:28:27.841074 | controller | repo: downloading from remote: extras-common
2025-10-13 13:28:27.841109 | controller | CentOS Stream 9 - Extras packages               1.4 MB/s |  20 kB     00:00
2025-10-13 13:28:27.841143 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT.
2025-10-13 13:28:27.841177 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-10-13 13:28:27.841211 | controller | Completion plugin: Generating completion cache...
2025-10-13 13:28:27.841245 | controller | Metadata cache created.
2025-10-13 13:28:27.841298 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.798279
2025-10-13 13:28:27.866319 | 
2025-10-13 13:28:27.866447 | PLAY RECAP
2025-10-13 13:28:27.866502 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-13 13:28:27.866538 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-13 13:28:27.866563 | 
2025-10-13 13:28:27.988631 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-13 13:28:27.989425 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 13:28:28.535128 | 
2025-10-13 13:28:28.535233 | PLAY [all]
2025-10-13 13:28:28.556262 | 
2025-10-13 13:28:28.556341 | TASK [Install binary dependencies]
2025-10-13 13:28:28.616382 | controller | ok
2025-10-13 13:28:28.639229 | 
2025-10-13 13:28:28.639317 | TASK [bindep : Include find tasks]
2025-10-13 13:28:28.667680 | controller | ok
2025-10-13 13:28:28.674764 | controller | included: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-13 13:28:28.680825 | 
2025-10-13 13:28:28.680886 | TASK [bindep : Look for bindep.txt]
2025-10-13 13:28:29.089689 | controller | ok
2025-10-13 13:28:29.108784 | 
2025-10-13 13:28:29.110215 | TASK [bindep : Define bindep_file fact]
2025-10-13 13:28:29.154342 | controller | ok
2025-10-13 13:28:29.159698 | 
2025-10-13 13:28:29.159775 | TASK [bindep : Look for other-requirements.txt]
2025-10-13 13:28:29.184807 | controller | skipping: Conditional result was False
2025-10-13 13:28:29.191505 | 
2025-10-13 13:28:29.191593 | TASK [bindep : Define bindep_file fact]
2025-10-13 13:28:29.233553 | controller | skipping: Conditional result was False
2025-10-13 13:28:29.246206 | 
2025-10-13 13:28:29.246301 | TASK [bindep : Look for bindep fallback file]
2025-10-13 13:28:29.281912 | controller | skipping: Conditional result was False
2025-10-13 13:28:29.289987 | 
2025-10-13 13:28:29.290076 | TASK [bindep : Define bindep_file fact]
2025-10-13 13:28:29.315229 | controller | skipping: Conditional result was False
2025-10-13 13:28:29.323580 | 
2025-10-13 13:28:29.323708 | TASK [bindep : Include bindep tasks]
2025-10-13 13:28:29.359461 | controller | ok
2025-10-13 13:28:29.369606 | controller | included: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-10-13 13:28:29.382711 | 
2025-10-13 13:28:29.382797 | TASK [bindep : Look for bindep command]
2025-10-13 13:28:29.417750 | controller | skipping: Conditional result was False
2025-10-13 13:28:29.424976 | 
2025-10-13 13:28:29.425042 | TASK [bindep : Check for system bindep]
2025-10-13 13:28:29.961405 | controller | ok: Runtime: 0:00:00.006722
2025-10-13 13:28:29.971989 | 
2025-10-13 13:28:29.972125 | TASK [bindep : Define bindep_command fact]
2025-10-13 13:28:29.998282 | controller | skipping: Conditional result was False
2025-10-13 13:28:30.004479 | 
2025-10-13 13:28:30.004546 | TASK [bindep : Include install tasks]
2025-10-13 13:28:30.033378 | controller | ok
2025-10-13 13:28:30.041916 | controller | included: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-10-13 13:28:30.050655 | 
2025-10-13 13:28:30.050729 | TASK [bindep : Create temp dir for bindep]
2025-10-13 13:28:30.404457 | controller | changed
2025-10-13 13:28:30.412456 | 
2025-10-13 13:28:30.412540 | TASK [Ensure we have pip dependencies]
2025-10-13 13:28:30.435262 | controller | ok
2025-10-13 13:28:30.468131 | 
2025-10-13 13:28:30.468205 | TASK [ensure-pip : Check if pip is installed]
2025-10-13 09:28:30.755951 | controller | /usr/bin/pip3
2025-10-13 09:28:30.778113 | controller | /usr/bin/python3: No module named wheel
2025-10-13 13:28:31.000686 | controller | ok: Runtime: 0:00:00.032176
2025-10-13 13:28:31.006623 | 
2025-10-13 13:28:31.006706 | LOOP [ensure-pip : Install pip from packages]
2025-10-13 13:28:31.034944 | controller | ok: "/var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-10-13 13:28:31.049081 | controller | included: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-10-13 13:28:31.069948 | 
2025-10-13 13:28:31.070028 | TASK [ensure-pip : Install Python 3 pip]
2025-10-13 13:28:33.497715 | controller | changed
2025-10-13 13:28:33.505152 | 
2025-10-13 13:28:33.505216 | TASK [ensure-pip : Check for EPEL repository]
2025-10-13 13:28:33.544028 | controller | skipping: Conditional result was False
2025-10-13 13:28:33.552003 | 
2025-10-13 13:28:33.552072 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-10-13 13:28:33.597240 | controller | skipping: Conditional result was False
2025-10-13 13:28:33.604552 | 
2025-10-13 13:28:33.604619 | TASK [ensure-pip : Install Python 2 pip]
2025-10-13 13:28:33.648829 | controller | skipping: Conditional result was False
2025-10-13 13:28:33.657141 | 
2025-10-13 13:28:33.657225 | TASK [ensure-pip : Ensure setuptools]
2025-10-13 13:28:33.681163 | controller | skipping: Conditional result was False
2025-10-13 13:28:33.688407 | 
2025-10-13 13:28:33.688473 | TASK [ensure-pip : Check for ensurepip module]
2025-10-13 13:28:34.223748 | controller | skipping: Conditional result was False
2025-10-13 13:28:34.242064 | 
2025-10-13 13:28:34.242224 | TASK [ensure-pip : Ensure python3-venv]
2025-10-13 13:28:34.273660 | controller | skipping: Conditional result was False
2025-10-13 13:28:34.289099 | 
2025-10-13 13:28:34.289284 | TASK [ensure-pip : Install pip from source]
2025-10-13 13:28:34.314534 | controller | skipping: Conditional result was False
2025-10-13 13:28:34.322540 | 
2025-10-13 13:28:34.322614 | TASK [ensure-pip : Probe for venv python full path]
2025-10-13 09:28:34.599580 | controller | /usr/bin/python3
2025-10-13 13:28:34.876553 | controller | ok: Runtime: 0:00:00.006415
2025-10-13 13:28:34.882635 | 
2025-10-13 13:28:34.882734 | TASK [ensure-pip : Set host default]
2025-10-13 13:28:34.932717 | controller | ok
2025-10-13 13:28:34.938518 | 
2025-10-13 13:28:34.938578 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-10-13 13:28:35.003450 | controller | ok
2025-10-13 13:28:35.016139 | 
2025-10-13 13:28:35.016202 | TASK [bindep : Install bindep into temporary venv]
2025-10-13 13:28:39.519624 | controller | changed
2025-10-13 13:28:39.525549 | 
2025-10-13 13:28:39.525620 | TASK [bindep : Define bindep_command]
2025-10-13 13:28:39.581231 | controller | ok
2025-10-13 13:28:39.588775 | 
2025-10-13 13:28:39.588863 | LOOP [bindep : Include package tasks]
2025-10-13 13:28:39.644329 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-10-13 13:28:39.644540 | controller | ok: All items complete
2025-10-13 13:28:39.644565 | 
2025-10-13 13:28:39.656038 | controller | included: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-10-13 13:28:39.667459 | 
2025-10-13 13:28:39.667530 | TASK [bindep : Define bindep_run fact]
2025-10-13 13:28:39.707774 | controller | ok
2025-10-13 13:28:39.712891 | 
2025-10-13 13:28:39.712952 | TASK [bindep : Get list of packages to install from bindep]
2025-10-13 09:28:41.245147 | controller | podman
2025-10-13 09:28:41.293874 | controller | python3-jmespath
2025-10-13 09:28:41.293991 | controller | python3-libvirt
2025-10-13 09:28:41.294027 | controller | python3-lxml
2025-10-13 09:28:41.294045 | controller | python3-netaddr
2025-10-13 13:28:41.750430 | controller | ok: Runtime: 0:00:01.309319
2025-10-13 13:28:41.756658 | 
2025-10-13 13:28:41.756741 | TASK [bindep : Install distro packages from bindep]
2025-10-13 13:29:46.336908 | controller | changed
2025-10-13 13:29:46.346590 | 
2025-10-13 13:29:46.346721 | TASK [bindep : Check that packages are installed]
2025-10-13 13:29:47.900961 | controller | ok: Runtime: 0:00:01.222505
2025-10-13 13:29:47.914251 | 
2025-10-13 13:29:47.914399 | TASK [bindep : Fail if we cannot install all packages]
2025-10-13 13:29:47.954846 | controller | skipping: Conditional result was False
2025-10-13 13:29:47.979739 | 
2025-10-13 13:29:47.979883 | TASK [Run test-setup role]
2025-10-13 13:29:48.012494 | controller | ok
2025-10-13 13:29:48.045362 | 
2025-10-13 13:29:48.045460 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-13 13:29:48.289376 | controller | ok
2025-10-13 13:29:48.301893 | 
2025-10-13 13:29:48.302054 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-13 13:29:48.855715 | controller | skipping: Conditional result was False
2025-10-13 13:29:48.909213 | 
2025-10-13 13:29:48.909370 | TASK [bindep : Remove bindep temp dir]
2025-10-13 13:29:49.326740 | controller | ok
2025-10-13 13:29:49.352481 | 
2025-10-13 13:29:49.352741 | PLAY RECAP
2025-10-13 13:29:49.352854 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-10-13 13:29:49.352961 | 
2025-10-13 13:29:49.533791 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 13:29:49.535003 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-13 13:29:50.126893 | 
2025-10-13 13:29:50.127033 | PLAY [all]
2025-10-13 13:29:50.147544 | 
2025-10-13 13:29:50.147619 | TASK [Abort when test_command variable is undefined]
2025-10-13 13:29:50.172600 | controller | skipping: Conditional result was False
2025-10-13 13:29:50.180014 | 
2025-10-13 13:29:50.180115 | TASK [Convert test_command to list]
2025-10-13 13:29:50.225531 | controller | skipping: Conditional result was False
2025-10-13 13:29:50.239176 | 
2025-10-13 13:29:50.239342 | TASK [Use test_command list]
2025-10-13 13:29:50.307523 | controller | ok
2025-10-13 13:29:50.319316 | 
2025-10-13 13:29:50.319445 | LOOP [Run test_command]
2025-10-13 13:29:50.729583 | controller | no check to run
2025-10-13 13:29:50.729934 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.005039
2025-10-13 13:29:50.770096 | 
2025-10-13 13:29:50.770282 | PLAY RECAP
2025-10-13 13:29:50.770343 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-13 13:29:50.770371 | 
2025-10-13 13:29:50.886942 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-13 13:29:50.888013 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 13:29:51.479084 | 
2025-10-13 13:29:51.479210 | PLAY [all]
2025-10-13 13:29:51.499045 | 
2025-10-13 13:29:51.499122 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-13 13:29:51.862458 | controller | changed: non-zero return code
2025-10-13 13:29:51.874148 | 
2025-10-13 13:29:51.874299 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-13 13:29:51.902425 | controller | skipping: Conditional result was False
2025-10-13 13:29:51.915288 | 
2025-10-13 13:29:51.915436 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-13 13:29:51.957549 | 
2025-10-13 13:29:51.957831 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-13 13:29:51.998612 | 
2025-10-13 13:29:51.998893 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-13 13:29:52.026638 | controller | skipping: Conditional result was False
2025-10-13 13:29:52.039818 | 
2025-10-13 13:29:52.039957 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-13 13:29:52.080741 | 
2025-10-13 13:29:52.081044 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-13 13:29:52.112511 | controller | skipping: Conditional result was False
2025-10-13 13:29:52.123532 | 
2025-10-13 13:29:52.123717 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-13 13:29:52.150816 | controller | skipping: Conditional result was False
2025-10-13 13:29:52.163275 | 
2025-10-13 13:29:52.163407 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-13 13:29:52.190553 | controller | skipping: Conditional result was False
2025-10-13 13:29:52.234020 | 
2025-10-13 13:29:52.234091 | PLAY RECAP
2025-10-13 13:29:52.234149 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-13 13:29:52.234177 | 
2025-10-13 13:29:52.377017 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 13:29:52.378819 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-13 13:29:53.049750 | 
2025-10-13 13:29:53.050005 | PLAY [all]
2025-10-13 13:29:53.069660 | 
2025-10-13 13:29:53.069757 | TASK [include_role : fetch-output]
2025-10-13 13:29:53.119960 | controller | ok
2025-10-13 13:29:53.138518 | 
2025-10-13 13:29:53.138615 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-13 13:29:53.214814 | controller | skipping: Conditional result was False
2025-10-13 13:29:53.223074 | 
2025-10-13 13:29:53.223173 | TASK [fetch-output : Set log path for single node]
2025-10-13 13:29:53.271782 | controller | ok
2025-10-13 13:29:53.283401 | 
2025-10-13 13:29:53.283542 | LOOP [fetch-output : Ensure local output dirs]
2025-10-13 13:29:53.782507 | controller -> localhost | ok: "/var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/work/logs"
2025-10-13 13:29:54.012938 | controller -> localhost | changed: "/var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/work/artifacts"
2025-10-13 13:29:54.234802 | controller -> localhost | changed: "/var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/work/docs"
2025-10-13 13:29:54.251345 | 
2025-10-13 13:29:54.251445 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-13 13:29:54.956156 | controller | changed: .d..t...... ./
2025-10-13 13:29:54.956428 | controller | changed: All items complete
2025-10-13 13:29:54.956456 | 
2025-10-13 13:29:55.559236 | controller | changed: .d..t...... ./
2025-10-13 13:29:56.072567 | controller | changed: .d..t...... ./
2025-10-13 13:29:56.101105 | 
2025-10-13 13:29:56.101316 | TASK [include_role : fetch-output-openshift]
2025-10-13 13:29:56.127722 | controller | skipping: Conditional result was False
2025-10-13 13:29:56.141363 | 
2025-10-13 13:29:56.141503 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-13 13:29:56.729334 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.013241
2025-10-13 13:29:56.996093 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.014418
2025-10-13 13:29:57.046598 | 
2025-10-13 13:29:57.046876 | PLAY [all]
2025-10-13 13:29:57.068006 | 
2025-10-13 13:29:57.068098 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-13 13:29:57.584195 | controller | changed
2025-10-13 13:29:57.624986 | 
2025-10-13 13:29:57.625083 | PLAY RECAP
2025-10-13 13:29:57.625128 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-13 13:29:57.625148 | 
2025-10-13 13:29:57.738235 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-13 13:29:57.739097 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-13 13:29:58.348144 | 
2025-10-13 13:29:58.348272 | PLAY [localhost]
2025-10-13 13:29:58.366905 | 
2025-10-13 13:29:58.366990 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-13 13:29:58.791939 | localhost | changed
2025-10-13 13:29:58.801139 | 
2025-10-13 13:29:58.801228 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-13 13:29:58.829701 | localhost | ok
2025-10-13 13:29:58.837965 | 
2025-10-13 13:29:58.838033 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-13 13:29:59.222435 | localhost | changed
2025-10-13 13:29:59.228352 | 
2025-10-13 13:29:59.228432 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-13 13:29:59.844346 | localhost | changed
2025-10-13 13:29:59.849449 | 
2025-10-13 13:29:59.849510 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-13 13:30:00.218687 | localhost | Identity added: /var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/work/tmp/ansible.jc3ns7a4 (/var/lib/zuul/builds/007ac2ac5cf04d858f37ae2d67e9e605/work/tmp/ansible.jc3ns7a4)
2025-10-13 13:30:00.218890 | localhost | ok: Runtime: 0:00:00.009952
2025-10-13 13:30:00.223211 | 
2025-10-13 13:30:00.223276 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-13 13:30:00.465637 | localhost | ok: Runtime: 0:00:00.005466
2025-10-13 13:30:00.475411 | 
2025-10-13 13:30:00.475479 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-13 13:30:00.558214 | localhost | changed
2025-10-13 13:30:00.563156 | 
2025-10-13 13:30:00.563219 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-13 13:30:00.961012 | localhost | changed
2025-10-13 13:30:00.980904 | 
2025-10-13 13:30:00.980968 | PLAY [localhost]
2025-10-13 13:30:00.992917 | 
2025-10-13 13:30:00.993018 | TASK [Generate bulk log download script]
2025-10-13 13:30:01.013451 | localhost | ok
2025-10-13 13:30:01.025242 | 
2025-10-13 13:30:01.025306 | TASK [local-log-download : Check API endpoint is defined]
2025-10-13 13:30:01.073369 | localhost | ok: All assertions passed
2025-10-13 13:30:01.077795 | 
2025-10-13 13:30:01.077855 | TASK [local-log-download : Create download script]
2025-10-13 13:30:01.591487 | localhost -> localhost | changed
2025-10-13 13:30:01.611800 | 
2025-10-13 13:30:01.612039 | TASK [Register quick-download link]
2025-10-13 13:30:01.638780 | localhost | ok
2025-10-13 13:30:01.697132 | 
2025-10-13 13:30:01.697250 | PLAY [logserver.rdoproject.org]
2025-10-13 13:30:01.706556 | 
2025-10-13 13:30:01.706614 | TASK [Set zuul-log-path fact]
2025-10-13 13:30:01.724552 | logserver.rdoproject.org | ok
2025-10-13 13:30:01.734077 | 
2025-10-13 13:30:01.734137 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 13:30:01.771096 | logserver.rdoproject.org | ok
2025-10-13 13:30:01.777082 | 
2025-10-13 13:30:01.777202 | TASK [upload-logs : Create log directories]
2025-10-13 13:30:02.521135 | logserver.rdoproject.org | changed
2025-10-13 13:30:02.528233 | 
2025-10-13 13:30:02.528375 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-13 13:30:02.808301 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004756
2025-10-13 13:30:02.813274 | 
2025-10-13 13:30:02.813336 | TASK [upload-logs : Upload logs to log server]
2025-10-13 13:30:03.510723 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-13 13:30:03.516836 | 
2025-10-13 13:30:03.516990 | LOOP [upload-logs : Compress console log and json output]
2025-10-13 13:30:03.588006 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 13:30:03.607613 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 13:30:03.622440 | 
2025-10-13 13:30:03.622608 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-13 13:30:03.693541 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 13:30:03.693823 | 
2025-10-13 13:30:03.702183 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 13:30:03.717809 | 
2025-10-13 13:30:03.717979 | LOOP [upload-logs : Upload console log and json output]