2025-10-03 09:59:51.297157 | Job console starting...
2025-10-03 09:59:51.311358 | Updating repositories
2025-10-03 09:59:51.345854 | Preparing job workspace
2025-10-03 09:59:55.525366 | Running Ansible setup...
2025-10-03 09:59:59.545691 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-03 10:00:00.162141 | 
2025-10-03 10:00:00.162334 | PLAY [localhost]
2025-10-03 10:00:00.187264 | 
2025-10-03 10:00:00.187430 | TASK [Gathering Facts]
2025-10-03 10:00:01.367150 | localhost | ok
2025-10-03 10:00:01.381882 | 
2025-10-03 10:00:01.381963 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-03 10:00:01.840372 | localhost -> localhost | changed
2025-10-03 10:00:01.847982 | 
2025-10-03 10:00:01.848073 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-03 10:00:02.846357 | localhost -> localhost | changed
2025-10-03 10:00:02.856753 | 
2025-10-03 10:00:02.856909 | TASK [Setup log path fact]
2025-10-03 10:00:02.902388 | localhost | ok
2025-10-03 10:00:02.917581 | 
2025-10-03 10:00:02.917790 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-03 10:00:02.946532 | localhost | ok
2025-10-03 10:00:02.961068 | 
2025-10-03 10:00:02.961256 | TASK [emit-job-header : Print job information]
2025-10-03 10:00:03.010905 | # Job Information
2025-10-03 10:00:03.011097 | Ansible Version: 2.15.12
2025-10-03 10:00:03.011123 | Job: cifmw-molecule-fix_python_encodings
2025-10-03 10:00:03.011142 | Pipeline: github-check
2025-10-03 10:00:03.011160 | Executor: ze02.softwarefactory-project.io
2025-10-03 10:00:03.011177 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3362
2025-10-03 10:00:03.011195 | Log URL (when completed): https://logserver.rdoproject.org/9a7/rdoproject.org/9a7b9c5e44364c6281f0fee749fa1edc/
2025-10-03 10:00:03.011213 | Event ID: 79314020-a03f-11f0-87f2-6df8ed647fba
2025-10-03 10:00:03.015379 | 
2025-10-03 10:00:03.015445 | LOOP [emit-job-header : Print node information]
2025-10-03 10:00:03.124364 | localhost | ok:
2025-10-03 10:00:03.124628 | localhost | # Node Information
2025-10-03 10:00:03.124655 | localhost | Inventory Hostname: controller
2025-10-03 10:00:03.124712 | localhost | Hostname: np0005468518
2025-10-03 10:00:03.124733 | localhost | Username: zuul
2025-10-03 10:00:03.124753 | localhost | Distro: CentOS 9
2025-10-03 10:00:03.124770 | localhost | Provider: vexxhost-nodepool-tripleo
2025-10-03 10:00:03.124787 | localhost | Region: RegionOne
2025-10-03 10:00:03.124803 | localhost | Label: cloud-centos-9-stream-tripleo
2025-10-03 10:00:03.124818 | localhost | Product Name: OpenStack Nova
2025-10-03 10:00:03.124834 | localhost | Interface IP: 38.102.83.136
2025-10-03 10:00:03.161659 | 
2025-10-03 10:00:03.161833 | PLAY [all]
2025-10-03 10:00:03.169767 | 
2025-10-03 10:00:03.169847 | TASK [Gather network facts]
2025-10-03 10:00:03.658797 | controller | ok
2025-10-03 10:00:03.676264 | 
2025-10-03 10:00:03.676383 | TASK [include_role : start-zuul-console]
2025-10-03 10:00:03.697341 | controller | ok
2025-10-03 10:00:03.710770 | 
2025-10-03 10:00:03.710912 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-03 10:00:04.175412 | controller | ok
2025-10-03 10:00:04.186188 | 
2025-10-03 10:00:04.186268 | TASK [include_role : add-build-sshkey]
2025-10-03 10:00:04.217604 | controller | ok
2025-10-03 10:00:04.233168 | 
2025-10-03 10:00:04.233310 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-03 10:00:04.545393 | controller -> localhost | ok
2025-10-03 10:00:04.551238 | 
2025-10-03 10:00:04.551302 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-03 10:00:04.583775 | controller | ok
2025-10-03 10:00:04.598947 | controller | included: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-03 10:00:04.605341 | 
2025-10-03 10:00:04.605403 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-03 10:00:05.325284 | controller -> localhost | Generating public/private rsa key pair.
2025-10-03 10:00:05.325579 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/work/9a7b9c5e44364c6281f0fee749fa1edc_id_rsa.
2025-10-03 10:00:05.325610 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/work/9a7b9c5e44364c6281f0fee749fa1edc_id_rsa.pub.
2025-10-03 10:00:05.325632 | controller -> localhost | The key fingerprint is:
2025-10-03 10:00:05.325651 | controller -> localhost | SHA256:3po90TDnwowANFbn+zjlZTwdo6IkP5yPr77XfCqon7M zuul-build-sshkey
2025-10-03 10:00:05.326182 | controller -> localhost | The key's randomart image is:
2025-10-03 10:00:05.326215 | controller -> localhost | +---[RSA 3072]----+
2025-10-03 10:00:05.326236 | controller -> localhost | |   .+.. .        |
2025-10-03 10:00:05.326257 | controller -> localhost | |   ... o         |
2025-10-03 10:00:05.326275 | controller -> localhost | |     .  .     o  |
2025-10-03 10:00:05.326294 | controller -> localhost | |      .  .o..o o |
2025-10-03 10:00:05.326312 | controller -> localhost | |      ..S+o** .  |
2025-10-03 10:00:05.326329 | controller -> localhost | |       *.O=+o.   |
2025-10-03 10:00:05.326346 | controller -> localhost | |        X.+=     |
2025-10-03 10:00:05.326363 | controller -> localhost | |        oX+ o .  |
2025-10-03 10:00:05.326379 | controller -> localhost | |      .+EB+o.o   |
2025-10-03 10:00:05.326396 | controller -> localhost | +----[SHA256]-----+
2025-10-03 10:00:05.326450 | controller -> localhost | ok: Runtime: 0:00:00.094098
2025-10-03 10:00:05.336726 | 
2025-10-03 10:00:05.336904 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-03 10:00:05.378922 | controller | ok
2025-10-03 10:00:05.389543 | controller | included: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-03 10:00:05.408775 | 
2025-10-03 10:00:05.408865 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-03 10:00:05.433658 | controller | skipping: Conditional result was False
2025-10-03 10:00:05.439903 | 
2025-10-03 10:00:05.439998 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-03 10:00:05.957556 | controller | changed
2025-10-03 10:00:05.971023 | 
2025-10-03 10:00:05.971237 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-03 10:00:06.223049 | controller | ok
2025-10-03 10:00:06.231101 | 
2025-10-03 10:00:06.231213 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-03 10:00:07.100503 | controller | changed
2025-10-03 10:00:07.115120 | 
2025-10-03 10:00:07.115309 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-03 10:00:07.959519 | controller | changed
2025-10-03 10:00:07.965523 | 
2025-10-03 10:00:07.965600 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-03 10:00:08.014685 | controller | skipping: Conditional result was False
2025-10-03 10:00:08.029576 | 
2025-10-03 10:00:08.029800 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-03 10:00:08.483236 | controller -> localhost | changed
2025-10-03 10:00:08.494337 | 
2025-10-03 10:00:08.494415 | TASK [add-build-sshkey : Add back temp key]
2025-10-03 10:00:08.771026 | controller -> localhost | Identity added: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/work/9a7b9c5e44364c6281f0fee749fa1edc_id_rsa (zuul-build-sshkey)
2025-10-03 10:00:08.771269 | controller -> localhost | ok: Runtime: 0:00:00.010625
2025-10-03 10:00:08.777228 | 
2025-10-03 10:00:08.777296 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-03 10:00:09.197113 | controller | ok
2025-10-03 10:00:09.202126 | 
2025-10-03 10:00:09.202199 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-03 10:00:09.237499 | controller | skipping: Conditional result was False
2025-10-03 10:00:09.248386 | 
2025-10-03 10:00:09.248502 | TASK [include_role : validate-host]
2025-10-03 10:00:09.278582 | controller | ok
2025-10-03 10:00:09.300298 | 
2025-10-03 10:00:09.300444 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-03 10:00:09.330847 | controller | ok
2025-10-03 10:00:09.335628 | 
2025-10-03 10:00:09.335713 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-03 10:00:09.596430 | controller -> localhost | ok
2025-10-03 10:00:09.607393 | 
2025-10-03 10:00:09.607549 | TASK [validate-host : Collect information about the host]
2025-10-03 10:00:10.343782 | controller | ok
2025-10-03 10:00:10.359697 | 
2025-10-03 10:00:10.359848 | TASK [validate-host : Sanitize hostname]
2025-10-03 10:00:10.414815 | controller | ok
2025-10-03 10:00:10.424485 | 
2025-10-03 10:00:10.424706 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-03 10:00:11.012199 | controller -> localhost | changed
2025-10-03 10:00:11.019087 | 
2025-10-03 10:00:11.019161 | TASK [validate-host : Collect information about zuul worker]
2025-10-03 10:00:11.503538 | controller | ok
2025-10-03 10:00:11.513215 | 
2025-10-03 10:00:11.513317 | TASK [validate-host : Write out all zuul information for each host]
2025-10-03 10:00:12.114085 | controller -> localhost | changed
2025-10-03 10:00:12.129505 | 
2025-10-03 10:00:12.129611 | TASK [include_role : prepare-workspace-openshift]
2025-10-03 10:00:12.154775 | controller | skipping: Conditional result was False
2025-10-03 10:00:12.163976 | 
2025-10-03 10:00:12.164061 | TASK [include_role : remove-zuul-sshkey]
2025-10-03 10:00:12.190110 | controller | skipping: Conditional result was False
2025-10-03 10:00:12.196248 | 
2025-10-03 10:00:12.196322 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-03 10:00:12.497455 | controller | ok: "logs"
2025-10-03 10:00:12.499841 | controller | ok: All items complete
2025-10-03 10:00:12.499894 | 
2025-10-03 10:00:12.779225 | controller | ok: "artifacts"
2025-10-03 10:00:13.044504 | controller | ok: "docs"
2025-10-03 10:00:13.067454 | 
2025-10-03 10:00:13.067746 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-03 10:00:13.392063 | controller | changed: "logs"
2025-10-03 10:00:13.658928 | controller | changed: "artifacts"
2025-10-03 10:00:13.900836 | controller | changed: "docs"
2025-10-03 10:00:13.967797 | 
2025-10-03 10:00:13.967929 | PLAY RECAP
2025-10-03 10:00:13.967974 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-03 10:00:13.968006 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-03 10:00:13.968032 | 
2025-10-03 10:00:14.122101 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-03 10:00:14.123144 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-03 10:00:14.867579 | 
2025-10-03 10:00:14.867783 | PLAY [localhost]
2025-10-03 10:00:14.887054 | 
2025-10-03 10:00:14.887218 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-10-03 10:00:15.364434 | localhost | ok
2025-10-03 10:00:15.370134 | 
2025-10-03 10:00:15.370215 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-10-03 10:00:16.190466 | localhost | changed
2025-10-03 10:00:16.249085 | 
2025-10-03 10:00:16.249215 | PLAY [all]
2025-10-03 10:00:16.278502 | 
2025-10-03 10:00:16.282067 | TASK [include_role : prepare-workspace]
2025-10-03 10:00:16.340725 | controller | ok
2025-10-03 10:00:16.385397 | 
2025-10-03 10:00:16.385574 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-03 10:00:16.851036 | controller | ok
2025-10-03 10:00:16.859499 | 
2025-10-03 10:00:16.859614 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-03 10:00:18.961332 | controller | Output suppressed because no_log was given
2025-10-03 10:00:18.973181 | 
2025-10-03 10:00:18.973337 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-03 10:00:19.336652 | controller | changed: "logs"
2025-10-03 10:00:19.579716 | controller | changed: "artifacts"
2025-10-03 10:00:19.826780 | controller | changed: "docs"
2025-10-03 10:00:19.844012 | 
2025-10-03 10:00:19.844187 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-03 10:00:20.150260 | controller | changed: "logs"
2025-10-03 10:00:20.150633 | controller | changed: All items complete
2025-10-03 10:00:20.150677 | 
2025-10-03 10:00:20.362708 | controller | changed: "artifacts"
2025-10-03 10:00:20.594140 | controller | changed: "docs"
2025-10-03 10:00:20.614125 | 
2025-10-03 10:00:20.614287 | TASK [Check if worker can sudo]
2025-10-03 10:00:21.173122 | controller | ok: Runtime: 0:00:00.044864
2025-10-03 10:00:21.181379 | 
2025-10-03 10:00:21.181530 | TASK [configure-mirrors : Gather needed facts]
2025-10-03 10:00:21.239413 | controller | skipping: Conditional result was False
2025-10-03 10:00:21.246377 | 
2025-10-03 10:00:21.246518 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-10-03 10:00:21.378536 | controller | ok
2025-10-03 10:00:21.437723 | controller | included: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-10-03 10:00:21.446351 | 
2025-10-03 10:00:21.446534 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-10-03 10:00:21.745088 | controller | ok
2025-10-03 10:00:21.757891 | 
2025-10-03 10:00:21.758044 | LOOP [configure-mirrors : Include OS-specific variables]
2025-10-03 10:00:21.846955 | controller | ok: "/var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-10-03 10:00:21.866031 | 
2025-10-03 10:00:21.866168 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-10-03 10:00:22.802264 | controller | changed
2025-10-03 10:00:22.814879 | 
2025-10-03 10:00:22.815007 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-10-03 10:00:22.913854 | controller | ok: "/var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-10-03 10:00:22.914108 | controller | ok: All items complete
2025-10-03 10:00:22.914140 | 
2025-10-03 10:00:22.973079 | controller | included: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-10-03 10:00:22.981159 | 
2025-10-03 10:00:22.981242 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-10-03 10:00:23.947430 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-10-03 10:00:24.843817 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-10-03 10:00:24.868248 | 
2025-10-03 10:00:24.868418 | TASK [configure-mirrors : Disable deltrarpm]
2025-10-03 10:00:25.509246 | controller | changed: section and option added
2025-10-03 10:00:25.543594 | 
2025-10-03 10:00:25.543811 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-10-03 10:00:26.685128 | controller | 29 files removed
2025-10-03 10:00:26.685398 | controller | ok: Item: dnf clean all Runtime: 0:00:00.835357
2025-10-03 10:00:26.685438 | controller | changed: All items complete
2025-10-03 10:00:26.685458 | 
2025-10-03 10:00:37.774389 | 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-03 10:00:37.774567 | controller | DNF version: 4.14.0
2025-10-03 10:00:37.774602 | controller | cachedir: /var/cache/dnf
2025-10-03 10:00:37.774629 | controller | Making cache files for all metadata files.
2025-10-03 10:00:37.779158 | controller | baseos: has expired and will be refreshed.
2025-10-03 10:00:37.779207 | controller | appstream: has expired and will be refreshed.
2025-10-03 10:00:37.779229 | controller | crb: has expired and will be refreshed.
2025-10-03 10:00:37.779257 | controller | extras-common: has expired and will be refreshed.
2025-10-03 10:00:37.779275 | controller | repo: downloading from remote: baseos
2025-10-03 10:00:37.779293 | controller | CentOS Stream 9 - BaseOS                         57 MB/s | 8.8 MB     00:00
2025-10-03 10:00:37.779310 | controller | baseos: using metadata from Tue 30 Sep 2025 01:12:56 PM EDT.
2025-10-03 10:00:37.779327 | controller | repo: downloading from remote: appstream
2025-10-03 10:00:37.779346 | controller | CentOS Stream 9 - AppStream                      48 MB/s |  25 MB     00:00
2025-10-03 10:00:37.779363 | controller | appstream: using metadata from Tue 30 Sep 2025 01:16:29 PM EDT.
2025-10-03 10:00:37.779379 | controller | repo: downloading from remote: crb
2025-10-03 10:00:37.779394 | controller | CentOS Stream 9 - CRB                            70 MB/s | 7.1 MB     00:00
2025-10-03 10:00:37.779410 | controller | crb: using metadata from Tue 30 Sep 2025 01:20:54 PM EDT.
2025-10-03 10:00:37.779426 | controller | repo: downloading from remote: extras-common
2025-10-03 10:00:37.779447 | controller | CentOS Stream 9 - Extras packages               1.0 MB/s |  20 kB     00:00
2025-10-03 10:00:37.779472 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT.
2025-10-03 10:00:37.779490 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-10-03 10:00:37.779507 | controller | Completion plugin: Generating completion cache...
2025-10-03 10:00:37.779531 | controller | Metadata cache created.
2025-10-03 10:00:37.779563 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.802729
2025-10-03 10:00:37.814926 | 
2025-10-03 10:00:37.815175 | PLAY RECAP
2025-10-03 10:00:37.815226 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-03 10:00:37.815252 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-03 10:00:37.815268 | 
2025-10-03 10:00:38.178958 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-03 10:00:38.180278 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-03 10:00:39.903909 | 
2025-10-03 10:00:39.904136 | PLAY [all]
2025-10-03 10:00:39.929597 | 
2025-10-03 10:00:39.929811 | TASK [Install binary dependencies]
2025-10-03 10:00:40.033067 | controller | ok
2025-10-03 10:00:40.087633 | 
2025-10-03 10:00:40.087872 | TASK [bindep : Include find tasks]
2025-10-03 10:00:40.143774 | controller | ok
2025-10-03 10:00:40.155678 | controller | included: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-03 10:00:40.164759 | 
2025-10-03 10:00:40.164960 | TASK [bindep : Look for bindep.txt]
2025-10-03 10:00:40.642613 | controller | ok
2025-10-03 10:00:40.655320 | 
2025-10-03 10:00:40.655433 | TASK [bindep : Define bindep_file fact]
2025-10-03 10:00:40.716872 | controller | ok
2025-10-03 10:00:40.722448 | 
2025-10-03 10:00:40.722523 | TASK [bindep : Look for other-requirements.txt]
2025-10-03 10:00:40.756971 | controller | skipping: Conditional result was False
2025-10-03 10:00:40.763370 | 
2025-10-03 10:00:40.763448 | TASK [bindep : Define bindep_file fact]
2025-10-03 10:00:40.787745 | controller | skipping: Conditional result was False
2025-10-03 10:00:40.794190 | 
2025-10-03 10:00:40.794266 | TASK [bindep : Look for bindep fallback file]
2025-10-03 10:00:40.818978 | controller | skipping: Conditional result was False
2025-10-03 10:00:40.826309 | 
2025-10-03 10:00:40.826459 | TASK [bindep : Define bindep_file fact]
2025-10-03 10:00:40.863323 | controller | skipping: Conditional result was False
2025-10-03 10:00:40.872283 | 
2025-10-03 10:00:40.872382 | TASK [bindep : Include bindep tasks]
2025-10-03 10:00:40.905858 | controller | ok
2025-10-03 10:00:40.924971 | controller | included: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-10-03 10:00:40.937427 | 
2025-10-03 10:00:40.937526 | TASK [bindep : Look for bindep command]
2025-10-03 10:00:41.003315 | controller | skipping: Conditional result was False
2025-10-03 10:00:41.010315 | 
2025-10-03 10:00:41.010392 | TASK [bindep : Check for system bindep]
2025-10-03 10:00:41.591399 | controller | ok: Runtime: 0:00:00.005290
2025-10-03 10:00:41.597973 | 
2025-10-03 10:00:41.598070 | TASK [bindep : Define bindep_command fact]
2025-10-03 10:00:41.643462 | controller | skipping: Conditional result was False
2025-10-03 10:00:41.651252 | 
2025-10-03 10:00:41.651479 | TASK [bindep : Include install tasks]
2025-10-03 10:00:41.711627 | controller | ok
2025-10-03 10:00:41.720107 | controller | included: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-10-03 10:00:41.730641 | 
2025-10-03 10:00:41.730743 | TASK [bindep : Create temp dir for bindep]
2025-10-03 10:00:42.173903 | controller | changed
2025-10-03 10:00:42.180061 | 
2025-10-03 10:00:42.180128 | TASK [Ensure we have pip dependencies]
2025-10-03 10:00:42.227486 | controller | ok
2025-10-03 10:00:42.306373 | 
2025-10-03 10:00:42.306535 | TASK [ensure-pip : Check if pip is installed]
2025-10-03 06:00:42.586939 | controller | /usr/bin/pip3
2025-10-03 06:00:42.614497 | controller | /usr/bin/python3: No module named wheel
2025-10-03 10:00:42.856338 | controller | ok: Runtime: 0:00:00.037483
2025-10-03 10:00:42.862731 | 
2025-10-03 10:00:42.862802 | LOOP [ensure-pip : Install pip from packages]
2025-10-03 10:00:42.900777 | controller | ok: "/var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-10-03 10:00:42.918030 | controller | included: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-10-03 10:00:42.928074 | 
2025-10-03 10:00:42.928136 | TASK [ensure-pip : Install Python 3 pip]
2025-10-03 10:00:45.497385 | controller | changed
2025-10-03 10:00:45.502843 | 
2025-10-03 10:00:45.502906 | TASK [ensure-pip : Check for EPEL repository]
2025-10-03 10:00:45.563277 | controller | skipping: Conditional result was False
2025-10-03 10:00:45.571030 | 
2025-10-03 10:00:45.571121 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-10-03 10:00:45.634058 | controller | skipping: Conditional result was False
2025-10-03 10:00:45.649712 | 
2025-10-03 10:00:45.649888 | TASK [ensure-pip : Install Python 2 pip]
2025-10-03 10:00:45.695482 | controller | skipping: Conditional result was False
2025-10-03 10:00:45.702083 | 
2025-10-03 10:00:45.702154 | TASK [ensure-pip : Ensure setuptools]
2025-10-03 10:00:45.726314 | controller | skipping: Conditional result was False
2025-10-03 10:00:45.732801 | 
2025-10-03 10:00:45.732871 | TASK [ensure-pip : Check for ensurepip module]
2025-10-03 10:00:46.280268 | controller | skipping: Conditional result was False
2025-10-03 10:00:46.291508 | 
2025-10-03 10:00:46.291688 | TASK [ensure-pip : Ensure python3-venv]
2025-10-03 10:00:46.309573 | controller | skipping: Conditional result was False
2025-10-03 10:00:46.321334 | 
2025-10-03 10:00:46.321513 | TASK [ensure-pip : Install pip from source]
2025-10-03 10:00:46.339034 | controller | skipping: Conditional result was False
2025-10-03 10:00:46.349582 | 
2025-10-03 10:00:46.349811 | TASK [ensure-pip : Probe for venv python full path]
2025-10-03 06:00:46.646766 | controller | /usr/bin/python3
2025-10-03 10:00:46.899265 | controller | ok: Runtime: 0:00:00.008503
2025-10-03 10:00:46.906124 | 
2025-10-03 10:00:46.906198 | TASK [ensure-pip : Set host default]
2025-10-03 10:00:46.959836 | controller | ok
2025-10-03 10:00:46.980988 | 
2025-10-03 10:00:46.981159 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-10-03 10:00:47.047053 | controller | ok
2025-10-03 10:00:47.057987 | 
2025-10-03 10:00:47.058060 | TASK [bindep : Install bindep into temporary venv]
2025-10-03 10:00:51.575366 | controller | changed
2025-10-03 10:00:51.582573 | 
2025-10-03 10:00:51.582733 | TASK [bindep : Define bindep_command]
2025-10-03 10:00:51.626184 | controller | ok
2025-10-03 10:00:51.634118 | 
2025-10-03 10:00:51.634254 | LOOP [bindep : Include package tasks]
2025-10-03 10:00:51.701746 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-10-03 10:00:51.702083 | controller | ok: All items complete
2025-10-03 10:00:51.702116 | 
2025-10-03 10:00:51.723462 | controller | included: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-10-03 10:00:51.742544 | 
2025-10-03 10:00:51.742762 | TASK [bindep : Define bindep_run fact]
2025-10-03 10:00:51.778203 | controller | ok
2025-10-03 10:00:51.785925 | 
2025-10-03 10:00:51.786009 | TASK [bindep : Get list of packages to install from bindep]
2025-10-03 06:00:53.238394 | controller | podman
2025-10-03 06:00:53.276666 | controller | python3-jmespath
2025-10-03 06:00:53.276724 | controller | python3-libvirt
2025-10-03 06:00:53.276732 | controller | python3-lxml
2025-10-03 06:00:53.276740 | controller | python3-netaddr
2025-10-03 10:00:53.341503 | controller | ok: Runtime: 0:00:01.183412
2025-10-03 10:00:53.354825 | 
2025-10-03 10:00:53.354986 | TASK [bindep : Install distro packages from bindep]
2025-10-03 10:02:01.949902 | controller | changed
2025-10-03 10:02:01.955844 | 
2025-10-03 10:02:01.955910 | TASK [bindep : Check that packages are installed]
2025-10-03 10:02:03.487847 | controller | ok: Runtime: 0:00:01.112145
2025-10-03 10:02:03.497022 | 
2025-10-03 10:02:03.497138 | TASK [bindep : Fail if we cannot install all packages]
2025-10-03 10:02:03.544909 | controller | skipping: Conditional result was False
2025-10-03 10:02:03.567753 | 
2025-10-03 10:02:03.567922 | TASK [Run test-setup role]
2025-10-03 10:02:03.602432 | controller | ok
2025-10-03 10:02:03.628294 | 
2025-10-03 10:02:03.628397 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-03 10:02:03.878354 | controller | ok
2025-10-03 10:02:03.888118 | 
2025-10-03 10:02:03.888266 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-03 10:02:04.428899 | controller | skipping: Conditional result was False
2025-10-03 10:02:04.449080 | 
2025-10-03 10:02:04.449232 | TASK [bindep : Remove bindep temp dir]
2025-10-03 10:02:04.980578 | controller | ok
2025-10-03 10:02:04.996479 | 
2025-10-03 10:02:04.996546 | PLAY RECAP
2025-10-03 10:02:04.996590 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-10-03 10:02:04.996610 | 
2025-10-03 10:02:05.188683 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-03 10:02:05.189629 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-03 10:02:05.841167 | 
2025-10-03 10:02:05.841332 | PLAY [all]
2025-10-03 10:02:05.863887 | 
2025-10-03 10:02:05.864038 | TASK [Abort when test_command variable is undefined]
2025-10-03 10:02:05.889450 | controller | skipping: Conditional result was False
2025-10-03 10:02:05.896889 | 
2025-10-03 10:02:05.897075 | TASK [Convert test_command to list]
2025-10-03 10:02:05.952662 | controller | skipping: Conditional result was False
2025-10-03 10:02:05.960531 | 
2025-10-03 10:02:05.960631 | TASK [Use test_command list]
2025-10-03 10:02:06.017977 | controller | ok
2025-10-03 10:02:06.027722 | 
2025-10-03 10:02:06.027837 | LOOP [Run test_command]
2025-10-03 10:02:06.492174 | controller | no check to run
2025-10-03 10:02:06.492465 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.017836
2025-10-03 10:02:06.547593 | 
2025-10-03 10:02:06.547808 | PLAY RECAP
2025-10-03 10:02:06.547899 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-03 10:02:06.547945 | 
2025-10-03 10:02:06.691780 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-03 10:02:06.692779 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-03 10:02:07.316260 | 
2025-10-03 10:02:07.316444 | PLAY [all]
2025-10-03 10:02:07.339290 | 
2025-10-03 10:02:07.339517 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-03 10:02:07.820697 | controller | changed: non-zero return code
2025-10-03 10:02:07.833495 | 
2025-10-03 10:02:07.833715 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-03 10:02:07.875235 | controller | skipping: Conditional result was False
2025-10-03 10:02:07.881410 | 
2025-10-03 10:02:07.881481 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-03 10:02:07.910488 | 
2025-10-03 10:02:07.910707 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-03 10:02:07.945401 | 
2025-10-03 10:02:07.945576 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-03 10:02:07.960090 | controller | skipping: Conditional result was False
2025-10-03 10:02:07.967690 | 
2025-10-03 10:02:07.967763 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-03 10:02:07.991771 | 
2025-10-03 10:02:07.992036 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-03 10:02:08.010321 | controller | skipping: Conditional result was False
2025-10-03 10:02:08.017451 | 
2025-10-03 10:02:08.017569 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-03 10:02:08.032278 | controller | skipping: Conditional result was False
2025-10-03 10:02:08.039084 | 
2025-10-03 10:02:08.039164 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-03 10:02:08.053913 | controller | skipping: Conditional result was False
2025-10-03 10:02:08.079970 | 
2025-10-03 10:02:08.080068 | PLAY RECAP
2025-10-03 10:02:08.080115 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-03 10:02:08.080136 | 
2025-10-03 10:02:08.197356 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-03 10:02:08.198270 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-03 10:02:08.791829 | 
2025-10-03 10:02:08.791978 | PLAY [all]
2025-10-03 10:02:08.812201 | 
2025-10-03 10:02:08.812379 | TASK [include_role : fetch-output]
2025-10-03 10:02:08.842325 | controller | ok
2025-10-03 10:02:08.860595 | 
2025-10-03 10:02:08.860721 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-03 10:02:08.916019 | controller | skipping: Conditional result was False
2025-10-03 10:02:08.924543 | 
2025-10-03 10:02:08.924644 | TASK [fetch-output : Set log path for single node]
2025-10-03 10:02:08.970884 | controller | ok
2025-10-03 10:02:08.982163 | 
2025-10-03 10:02:08.982252 | LOOP [fetch-output : Ensure local output dirs]
2025-10-03 10:02:09.465008 | controller -> localhost | ok: "/var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/work/logs"
2025-10-03 10:02:09.679581 | controller -> localhost | changed: "/var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/work/artifacts"
2025-10-03 10:02:09.931478 | controller -> localhost | changed: "/var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/work/docs"
2025-10-03 10:02:09.951740 | 
2025-10-03 10:02:09.951917 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-03 10:02:10.726085 | controller | changed: .d..t...... ./
2025-10-03 10:02:10.726329 | controller | changed: All items complete
2025-10-03 10:02:10.726357 | 
2025-10-03 10:02:11.210636 | controller | changed: .d..t...... ./
2025-10-03 10:02:11.813485 | controller | changed: .d..t...... ./
2025-10-03 10:02:11.825778 | 
2025-10-03 10:02:11.825925 | TASK [include_role : fetch-output-openshift]
2025-10-03 10:02:11.840114 | controller | skipping: Conditional result was False
2025-10-03 10:02:11.847499 | 
2025-10-03 10:02:11.847609 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-03 10:02:12.342815 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.035709
2025-10-03 10:02:12.694600 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.013855
2025-10-03 10:02:12.730739 | 
2025-10-03 10:02:12.731216 | PLAY [all]
2025-10-03 10:02:12.750244 | 
2025-10-03 10:02:12.750346 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-03 10:02:13.359882 | controller | changed
2025-10-03 10:02:13.406356 | 
2025-10-03 10:02:13.406489 | PLAY RECAP
2025-10-03 10:02:13.406544 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-03 10:02:13.406570 | 
2025-10-03 10:02:13.579750 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-03 10:02:13.580726 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-03 10:02:14.399295 | 
2025-10-03 10:02:14.399470 | PLAY [localhost]
2025-10-03 10:02:14.420213 | 
2025-10-03 10:02:14.420364 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-03 10:02:14.981416 | localhost | changed
2025-10-03 10:02:14.988640 | 
2025-10-03 10:02:14.988756 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-03 10:02:15.041372 | localhost | ok
2025-10-03 10:02:15.058147 | 
2025-10-03 10:02:15.058263 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-03 10:02:15.536115 | localhost | changed
2025-10-03 10:02:15.546008 | 
2025-10-03 10:02:15.546135 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-03 10:02:16.578098 | localhost | changed
2025-10-03 10:02:16.584125 | 
2025-10-03 10:02:16.584206 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-03 10:02:17.402304 | localhost | Identity added: /var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/work/tmp/ansible.32805uih (/var/lib/zuul/builds/9a7b9c5e44364c6281f0fee749fa1edc/work/tmp/ansible.32805uih)
2025-10-03 10:02:17.402548 | localhost | ok: Runtime: 0:00:00.012718
2025-10-03 10:02:17.409966 | 
2025-10-03 10:02:17.410060 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-03 10:02:17.831722 | localhost | ok: Runtime: 0:00:00.012339
2025-10-03 10:02:17.838628 | 
2025-10-03 10:02:17.838757 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-03 10:02:17.910893 | localhost | changed
2025-10-03 10:02:17.915983 | 
2025-10-03 10:02:17.916051 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-03 10:02:18.411992 | localhost | changed
2025-10-03 10:02:18.440932 | 
2025-10-03 10:02:18.441078 | PLAY [localhost]
2025-10-03 10:02:18.461888 | 
2025-10-03 10:02:18.462019 | TASK [Generate bulk log download script]
2025-10-03 10:02:18.493236 | localhost | ok
2025-10-03 10:02:18.508708 | 
2025-10-03 10:02:18.508856 | TASK [local-log-download : Check API endpoint is defined]
2025-10-03 10:02:18.538372 | localhost | ok: All assertions passed
2025-10-03 10:02:18.550818 | 
2025-10-03 10:02:18.550966 | TASK [local-log-download : Create download script]
2025-10-03 10:02:19.025084 | localhost -> localhost | changed
2025-10-03 10:02:19.062987 | 
2025-10-03 10:02:19.063133 | TASK [Register quick-download link]
2025-10-03 10:02:19.092911 | localhost | ok
2025-10-03 10:02:19.114145 | 
2025-10-03 10:02:19.114253 | PLAY [logserver.rdoproject.org]
2025-10-03 10:02:19.125943 | 
2025-10-03 10:02:19.126035 | TASK [Set zuul-log-path fact]
2025-10-03 10:02:19.144480 | logserver.rdoproject.org | ok
2025-10-03 10:02:19.162843 | 
2025-10-03 10:02:19.162976 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-03 10:02:19.190030 | logserver.rdoproject.org | ok
2025-10-03 10:02:19.198713 | 
2025-10-03 10:02:19.198792 | TASK [upload-logs : Create log directories]
2025-10-03 10:02:19.944019 | logserver.rdoproject.org | changed
2025-10-03 10:02:19.954953 | 
2025-10-03 10:02:19.955116 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-03 10:02:20.270979 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.007390
2025-10-03 10:02:20.277710 | 
2025-10-03 10:02:20.277799 | TASK [upload-logs : Upload logs to log server]
2025-10-03 10:02:20.936360 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-03 10:02:20.939629 | 
2025-10-03 10:02:20.939718 | LOOP [upload-logs : Compress console log and json output]
2025-10-03 10:02:21.009403 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-03 10:02:21.017622 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-03 10:02:21.025607 | 
2025-10-03 10:02:21.025737 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-03 10:02:21.096389 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-03 10:02:21.096713 | 
2025-10-03 10:02:21.097464 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-03 10:02:21.108371 | 
2025-10-03 10:02:21.108505 | LOOP [upload-logs : Upload console log and json output]