2025-10-13 06:53:37.303185 | Job console starting...
2025-10-13 06:53:37.315306 | Updating repositories
2025-10-13 06:53:37.338689 | Preparing job workspace
2025-10-13 06:53:41.774323 | Running Ansible setup...
2025-10-13 06:53:45.677178 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-13 06:53:46.463373 | 
2025-10-13 06:53:46.463522 | PLAY [localhost]
2025-10-13 06:53:46.482294 | 
2025-10-13 06:53:46.482400 | TASK [Gathering Facts]
2025-10-13 06:53:48.058761 | localhost | ok
2025-10-13 06:53:48.074295 | 
2025-10-13 06:53:48.074375 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-13 06:53:48.467923 | localhost -> localhost | changed
2025-10-13 06:53:48.475065 | 
2025-10-13 06:53:48.475183 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-13 06:53:49.862445 | localhost -> localhost | changed
2025-10-13 06:53:49.872201 | 
2025-10-13 06:53:49.872319 | TASK [Setup log path fact]
2025-10-13 06:53:49.922896 | localhost | ok
2025-10-13 06:53:49.941442 | 
2025-10-13 06:53:49.941510 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 06:53:49.996269 | localhost | ok
2025-10-13 06:53:50.004186 | 
2025-10-13 06:53:50.004261 | TASK [emit-job-header : Print job information]
2025-10-13 06:53:50.088764 | # Job Information
2025-10-13 06:53:50.088910 | Ansible Version: 2.15.12
2025-10-13 06:53:50.088936 | Job: cifmw-molecule-cleanup_openstack
2025-10-13 06:53:50.088955 | Pipeline: github-check
2025-10-13 06:53:50.088973 | Executor: ze02.softwarefactory-project.io
2025-10-13 06:53:50.088991 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3237
2025-10-13 06:53:50.089010 | Log URL (when completed): https://logserver.rdoproject.org/86c/rdoproject.org/86c35fae9e0041d69c7c1fe19708e36f/
2025-10-13 06:53:50.089028 | Event ID: 0a621880-a801-11f0-8fd5-3020d4b2b2c2
2025-10-13 06:53:50.094365 | 
2025-10-13 06:53:50.094451 | LOOP [emit-job-header : Print node information]
2025-10-13 06:53:50.188284 | localhost | ok:
2025-10-13 06:53:50.188564 | localhost | # Node Information
2025-10-13 06:53:50.188602 | localhost | Inventory Hostname: controller
2025-10-13 06:53:50.188645 | localhost | Hostname: np0005482612
2025-10-13 06:53:50.188725 | localhost | Username: zuul
2025-10-13 06:53:50.188751 | localhost | Distro: CentOS 9
2025-10-13 06:53:50.188771 | localhost | Provider: vexxhost-nodepool-tripleo
2025-10-13 06:53:50.188802 | localhost | Region: RegionOne
2025-10-13 06:53:50.188823 | localhost | Label: cloud-centos-9-stream-tripleo
2025-10-13 06:53:50.188845 | localhost | Product Name: OpenStack Nova
2025-10-13 06:53:50.188866 | localhost | Interface IP: 38.102.83.163
2025-10-13 06:53:50.213913 | 
2025-10-13 06:53:50.214031 | PLAY [all]
2025-10-13 06:53:50.221675 | 
2025-10-13 06:53:50.221748 | TASK [Gather network facts]
2025-10-13 06:53:50.700713 | controller | ok
2025-10-13 06:53:50.728493 | 
2025-10-13 06:53:50.728642 | TASK [include_role : start-zuul-console]
2025-10-13 06:53:50.748294 | controller | ok
2025-10-13 06:53:50.766910 | 
2025-10-13 06:53:50.767110 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-13 06:53:51.145166 | controller | ok
2025-10-13 06:53:51.155236 | 
2025-10-13 06:53:51.155319 | TASK [include_role : add-build-sshkey]
2025-10-13 06:53:51.187937 | controller | ok
2025-10-13 06:53:51.219263 | 
2025-10-13 06:53:51.219384 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-13 06:53:51.569084 | controller -> localhost | ok
2025-10-13 06:53:51.581652 | 
2025-10-13 06:53:51.581798 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-13 06:53:51.619396 | controller | ok
2025-10-13 06:53:51.639166 | controller | included: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-13 06:53:51.646131 | 
2025-10-13 06:53:51.646227 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-13 06:53:53.455936 | controller -> localhost | Generating public/private rsa key pair.
2025-10-13 06:53:53.471376 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/work/86c35fae9e0041d69c7c1fe19708e36f_id_rsa.
2025-10-13 06:53:53.471449 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/work/86c35fae9e0041d69c7c1fe19708e36f_id_rsa.pub.
2025-10-13 06:53:53.471475 | controller -> localhost | The key fingerprint is:
2025-10-13 06:53:53.471496 | controller -> localhost | SHA256:qw2ZF6xjnz9MUzqpzWDGW1YSOCKswj8FKn1FwaDaPnk zuul-build-sshkey
2025-10-13 06:53:53.471517 | controller -> localhost | The key's randomart image is:
2025-10-13 06:53:53.471537 | controller -> localhost | +---[RSA 3072]----+
2025-10-13 06:53:53.471556 | controller -> localhost | |   ..+o. .       |
2025-10-13 06:53:53.471576 | controller -> localhost | |   oo + o .      |
2025-10-13 06:53:53.471595 | controller -> localhost | |..o..o . . .     |
2025-10-13 06:53:53.471614 | controller -> localhost | |o=o .. .  . o    |
2025-10-13 06:53:53.471632 | controller -> localhost | |o.o..  .S  *     |
2025-10-13 06:53:53.471650 | controller -> localhost | | . +   +=oO      |
2025-10-13 06:53:53.471671 | controller -> localhost | |  + E Boo@ o     |
2025-10-13 06:53:53.471717 | controller -> localhost | |   o . Bo.=      |
2025-10-13 06:53:53.471737 | controller -> localhost | |      . +...     |
2025-10-13 06:53:53.471757 | controller -> localhost | +----[SHA256]-----+
2025-10-13 06:53:53.471822 | controller -> localhost | ok: Runtime: 0:00:01.214795
2025-10-13 06:53:53.486906 | 
2025-10-13 06:53:53.487033 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-13 06:53:53.585207 | controller | ok
2025-10-13 06:53:53.607002 | controller | included: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-13 06:53:53.620120 | 
2025-10-13 06:53:53.620224 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-13 06:53:53.638167 | controller | skipping: Conditional result was False
2025-10-13 06:53:53.650815 | 
2025-10-13 06:53:53.650903 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-13 06:53:54.293904 | controller | changed
2025-10-13 06:53:54.300982 | 
2025-10-13 06:53:54.301096 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-13 06:53:54.592904 | controller | ok
2025-10-13 06:53:54.607333 | 
2025-10-13 06:53:54.607451 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-13 06:53:55.440730 | controller | changed
2025-10-13 06:53:55.446177 | 
2025-10-13 06:53:55.446245 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-13 06:53:56.454898 | controller | changed
2025-10-13 06:53:56.460718 | 
2025-10-13 06:53:56.460788 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-13 06:53:56.490542 | controller | skipping: Conditional result was False
2025-10-13 06:53:56.496750 | 
2025-10-13 06:53:56.496818 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-13 06:53:57.135907 | controller -> localhost | changed
2025-10-13 06:53:57.145917 | 
2025-10-13 06:53:57.145982 | TASK [add-build-sshkey : Add back temp key]
2025-10-13 06:53:57.592952 | controller -> localhost | Identity added: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/work/86c35fae9e0041d69c7c1fe19708e36f_id_rsa (zuul-build-sshkey)
2025-10-13 06:53:57.593151 | controller -> localhost | ok: Runtime: 0:00:00.009623
2025-10-13 06:53:57.599060 | 
2025-10-13 06:53:57.599121 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-13 06:53:58.155464 | controller | ok
2025-10-13 06:53:58.160446 | 
2025-10-13 06:53:58.160509 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-13 06:53:58.228564 | controller | skipping: Conditional result was False
2025-10-13 06:53:58.238257 | 
2025-10-13 06:53:58.238324 | TASK [include_role : validate-host]
2025-10-13 06:53:58.299211 | controller | ok
2025-10-13 06:53:58.401820 | 
2025-10-13 06:53:58.401941 | TASK [validate-host : Define zuul_info_dir fact]
2025-10-13 06:53:58.441144 | controller | ok
2025-10-13 06:53:58.446227 | 
2025-10-13 06:53:58.446290 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-10-13 06:53:58.788769 | controller -> localhost | ok
2025-10-13 06:53:58.794982 | 
2025-10-13 06:53:58.795051 | TASK [validate-host : Collect information about the host]
2025-10-13 06:53:59.621181 | controller | ok
2025-10-13 06:53:59.637075 | 
2025-10-13 06:53:59.637159 | TASK [validate-host : Sanitize hostname]
2025-10-13 06:53:59.848814 | controller | ok
2025-10-13 06:53:59.854604 | 
2025-10-13 06:53:59.854701 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-10-13 06:54:00.710004 | controller -> localhost | changed
2025-10-13 06:54:00.716527 | 
2025-10-13 06:54:00.716593 | TASK [validate-host : Collect information about zuul worker]
2025-10-13 06:54:01.359269 | controller | ok
2025-10-13 06:54:01.373428 | 
2025-10-13 06:54:01.375167 | TASK [validate-host : Write out all zuul information for each host]
2025-10-13 06:54:02.318777 | controller -> localhost | changed
2025-10-13 06:54:02.332525 | 
2025-10-13 06:54:02.332611 | TASK [include_role : prepare-workspace-openshift]
2025-10-13 06:54:02.398220 | controller | skipping: Conditional result was False
2025-10-13 06:54:02.409595 | 
2025-10-13 06:54:02.409697 | TASK [include_role : remove-zuul-sshkey]
2025-10-13 06:54:02.485660 | controller | skipping: Conditional result was False
2025-10-13 06:54:02.491719 | 
2025-10-13 06:54:02.491787 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-13 06:54:02.828309 | controller | ok: "logs"
2025-10-13 06:54:02.828695 | controller | ok: All items complete
2025-10-13 06:54:02.828738 | 
2025-10-13 06:54:03.052969 | controller | ok: "artifacts"
2025-10-13 06:54:03.289583 | controller | ok: "docs"
2025-10-13 06:54:03.297386 | 
2025-10-13 06:54:03.297548 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-13 06:54:03.630766 | controller | changed: "logs"
2025-10-13 06:54:03.893070 | controller | changed: "artifacts"
2025-10-13 06:54:04.138296 | controller | changed: "docs"
2025-10-13 06:54:04.214806 | 
2025-10-13 06:54:04.214896 | PLAY RECAP
2025-10-13 06:54:04.214942 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-10-13 06:54:04.214969 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-13 06:54:04.214987 | 
2025-10-13 06:54:04.550186 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-10-13 06:54:04.551080 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-13 06:54:05.558062 | 
2025-10-13 06:54:05.558244 | PLAY [localhost]
2025-10-13 06:54:05.581815 | 
2025-10-13 06:54:05.582149 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-10-13 06:54:06.383143 | localhost | ok
2025-10-13 06:54:06.390783 | 
2025-10-13 06:54:06.390862 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-10-13 06:54:07.451612 | localhost | changed
2025-10-13 06:54:07.489155 | 
2025-10-13 06:54:07.489249 | PLAY [all]
2025-10-13 06:54:07.511098 | 
2025-10-13 06:54:07.511166 | TASK [include_role : prepare-workspace]
2025-10-13 06:54:07.574120 | controller | ok
2025-10-13 06:54:07.633799 | 
2025-10-13 06:54:07.633916 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-13 06:54:08.084698 | controller | ok
2025-10-13 06:54:08.094537 | 
2025-10-13 06:54:08.094611 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-13 06:54:10.195302 | controller | Output suppressed because no_log was given
2025-10-13 06:54:10.222957 | 
2025-10-13 06:54:10.223084 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-13 06:54:10.536544 | controller | changed: "logs"
2025-10-13 06:54:10.769750 | controller | changed: "artifacts"
2025-10-13 06:54:10.992551 | controller | changed: "docs"
2025-10-13 06:54:11.006296 | 
2025-10-13 06:54:11.006444 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-13 06:54:11.299740 | controller | changed: "logs"
2025-10-13 06:54:11.300055 | controller | changed: All items complete
2025-10-13 06:54:11.300086 | 
2025-10-13 06:54:11.503198 | controller | changed: "artifacts"
2025-10-13 06:54:11.751038 | controller | changed: "docs"
2025-10-13 06:54:11.780367 | 
2025-10-13 06:54:11.780483 | TASK [Check if worker can sudo]
2025-10-13 06:54:12.315114 | controller | ok: Runtime: 0:00:00.045138
2025-10-13 06:54:12.323328 | 
2025-10-13 06:54:12.323412 | TASK [configure-mirrors : Gather needed facts]
2025-10-13 06:54:12.389375 | controller | skipping: Conditional result was False
2025-10-13 06:54:12.395265 | 
2025-10-13 06:54:12.395329 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-10-13 06:54:12.484806 | controller | ok
2025-10-13 06:54:12.539742 | controller | included: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-10-13 06:54:12.553056 | 
2025-10-13 06:54:12.553125 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-10-13 06:54:12.870139 | controller | ok
2025-10-13 06:54:12.880039 | 
2025-10-13 06:54:12.880128 | LOOP [configure-mirrors : Include OS-specific variables]
2025-10-13 06:54:12.939385 | controller | ok: "/var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-10-13 06:54:12.955400 | 
2025-10-13 06:54:12.955463 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-10-13 06:54:13.876289 | controller | changed
2025-10-13 06:54:13.882365 | 
2025-10-13 06:54:13.882427 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-10-13 06:54:13.983035 | controller | ok: "/var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-10-13 06:54:13.983256 | controller | ok: All items complete
2025-10-13 06:54:13.983283 | 
2025-10-13 06:54:14.142434 | controller | included: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-10-13 06:54:14.150213 | 
2025-10-13 06:54:14.150281 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-10-13 06:54:15.126817 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-10-13 06:54:16.036702 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-10-13 06:54:16.052573 | 
2025-10-13 06:54:16.052730 | TASK [configure-mirrors : Disable deltrarpm]
2025-10-13 06:54:16.474852 | controller | changed: section and option added
2025-10-13 06:54:16.495980 | 
2025-10-13 06:54:16.496063 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-10-13 06:54:17.311245 | controller | 29 files removed
2025-10-13 06:54:17.311468 | controller | ok: Item: dnf clean all Runtime: 0:00:00.484391
2025-10-13 06:54:17.311510 | controller | changed: All items complete
2025-10-13 06:54:17.311531 | 
2025-10-13 06:54:28.130203 | 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 06:54:28.130372 | controller | DNF version: 4.14.0
2025-10-13 06:54:28.130431 | controller | cachedir: /var/cache/dnf
2025-10-13 06:54:28.130478 | controller | Making cache files for all metadata files.
2025-10-13 06:54:28.130522 | controller | baseos: has expired and will be refreshed.
2025-10-13 06:54:28.130564 | controller | appstream: has expired and will be refreshed.
2025-10-13 06:54:28.130605 | controller | crb: has expired and will be refreshed.
2025-10-13 06:54:28.130723 | controller | extras-common: has expired and will be refreshed.
2025-10-13 06:54:28.130782 | controller | repo: downloading from remote: baseos
2025-10-13 06:54:28.130828 | controller | CentOS Stream 9 - BaseOS                         70 MB/s | 8.8 MB     00:00
2025-10-13 06:54:28.130871 | controller | baseos: using metadata from Wed 08 Oct 2025 09:42:12 AM EDT.
2025-10-13 06:54:28.130913 | controller | repo: downloading from remote: appstream
2025-10-13 06:54:28.130954 | controller | CentOS Stream 9 - AppStream                     112 MB/s |  25 MB     00:00
2025-10-13 06:54:28.130994 | controller | appstream: using metadata from Wed 08 Oct 2025 09:45:45 AM EDT.
2025-10-13 06:54:28.131034 | controller | repo: downloading from remote: crb
2025-10-13 06:54:28.131075 | controller | CentOS Stream 9 - CRB                            87 MB/s | 7.2 MB     00:00
2025-10-13 06:54:28.131115 | controller | crb: using metadata from Wed 08 Oct 2025 09:50:07 AM EDT.
2025-10-13 06:54:28.131156 | controller | repo: downloading from remote: extras-common
2025-10-13 06:54:28.131197 | controller | CentOS Stream 9 - Extras packages               1.2 MB/s |  20 kB     00:00
2025-10-13 06:54:28.131238 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT.
2025-10-13 06:54:28.131278 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-10-13 06:54:28.131317 | controller | Completion plugin: Generating completion cache...
2025-10-13 06:54:28.131357 | controller | Metadata cache created.
2025-10-13 06:54:28.131416 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.550449
2025-10-13 06:54:28.178425 | 
2025-10-13 06:54:28.178571 | PLAY RECAP
2025-10-13 06:54:28.178629 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-10-13 06:54:28.178687 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-13 06:54:28.178720 | 
2025-10-13 06:54:28.299448 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-10-13 06:54:28.300321 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 06:54:28.844592 | 
2025-10-13 06:54:28.844751 | PLAY [all]
2025-10-13 06:54:28.867977 | 
2025-10-13 06:54:28.868058 | TASK [Install binary dependencies]
2025-10-13 06:54:28.918064 | controller | ok
2025-10-13 06:54:28.938438 | 
2025-10-13 06:54:28.938531 | TASK [bindep : Include find tasks]
2025-10-13 06:54:28.967540 | controller | ok
2025-10-13 06:54:28.975101 | controller | included: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-13 06:54:28.981286 | 
2025-10-13 06:54:28.981353 | TASK [bindep : Look for bindep.txt]
2025-10-13 06:54:29.414818 | controller | ok
2025-10-13 06:54:29.428865 | 
2025-10-13 06:54:29.429007 | TASK [bindep : Define bindep_file fact]
2025-10-13 06:54:29.468249 | controller | ok
2025-10-13 06:54:29.480855 | 
2025-10-13 06:54:29.480995 | TASK [bindep : Look for other-requirements.txt]
2025-10-13 06:54:29.509280 | controller | skipping: Conditional result was False
2025-10-13 06:54:29.520805 | 
2025-10-13 06:54:29.520907 | TASK [bindep : Define bindep_file fact]
2025-10-13 06:54:29.546379 | controller | skipping: Conditional result was False
2025-10-13 06:54:29.554485 | 
2025-10-13 06:54:29.554574 | TASK [bindep : Look for bindep fallback file]
2025-10-13 06:54:29.599739 | controller | skipping: Conditional result was False
2025-10-13 06:54:29.605659 | 
2025-10-13 06:54:29.605743 | TASK [bindep : Define bindep_file fact]
2025-10-13 06:54:29.630182 | controller | skipping: Conditional result was False
2025-10-13 06:54:29.636323 | 
2025-10-13 06:54:29.636387 | TASK [bindep : Include bindep tasks]
2025-10-13 06:54:29.667422 | controller | ok
2025-10-13 06:54:29.675077 | controller | included: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-10-13 06:54:29.682986 | 
2025-10-13 06:54:29.683047 | TASK [bindep : Look for bindep command]
2025-10-13 06:54:29.707351 | controller | skipping: Conditional result was False
2025-10-13 06:54:29.714320 | 
2025-10-13 06:54:29.714593 | TASK [bindep : Check for system bindep]
2025-10-13 06:54:30.250860 | controller | ok: Runtime: 0:00:00.005025
2025-10-13 06:54:30.264703 | 
2025-10-13 06:54:30.265070 | TASK [bindep : Define bindep_command fact]
2025-10-13 06:54:30.303607 | controller | skipping: Conditional result was False
2025-10-13 06:54:30.320229 | 
2025-10-13 06:54:30.320456 | TASK [bindep : Include install tasks]
2025-10-13 06:54:30.379330 | controller | ok
2025-10-13 06:54:30.395561 | controller | included: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-10-13 06:54:30.411088 | 
2025-10-13 06:54:30.411173 | TASK [bindep : Create temp dir for bindep]
2025-10-13 06:54:30.850549 | controller | changed
2025-10-13 06:54:30.865901 | 
2025-10-13 06:54:30.866029 | TASK [Ensure we have pip dependencies]
2025-10-13 06:54:30.890493 | controller | ok
2025-10-13 06:54:30.932539 | 
2025-10-13 06:54:30.932683 | TASK [ensure-pip : Check if pip is installed]
2025-10-13 02:54:31.244817 | controller | /usr/bin/pip3
2025-10-13 02:54:31.285880 | controller | /usr/bin/python3: No module named wheel
2025-10-13 06:54:31.476366 | controller | ok: Runtime: 0:00:00.053909
2025-10-13 06:54:31.482272 | 
2025-10-13 06:54:31.482340 | LOOP [ensure-pip : Install pip from packages]
2025-10-13 06:54:31.530165 | controller | ok: "/var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-10-13 06:54:31.545562 | controller | included: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-10-13 06:54:31.555894 | 
2025-10-13 06:54:31.555954 | TASK [ensure-pip : Install Python 3 pip]
2025-10-13 06:54:33.866477 | controller | changed
2025-10-13 06:54:33.872509 | 
2025-10-13 06:54:33.872573 | TASK [ensure-pip : Check for EPEL repository]
2025-10-13 06:54:33.939124 | controller | skipping: Conditional result was False
2025-10-13 06:54:33.948146 | 
2025-10-13 06:54:33.948251 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-10-13 06:54:34.018574 | controller | skipping: Conditional result was False
2025-10-13 06:54:34.025475 | 
2025-10-13 06:54:34.025558 | TASK [ensure-pip : Install Python 2 pip]
2025-10-13 06:54:34.070588 | controller | skipping: Conditional result was False
2025-10-13 06:54:34.078128 | 
2025-10-13 06:54:34.078214 | TASK [ensure-pip : Ensure setuptools]
2025-10-13 06:54:34.096564 | controller | skipping: Conditional result was False
2025-10-13 06:54:34.103236 | 
2025-10-13 06:54:34.103308 | TASK [ensure-pip : Check for ensurepip module]
2025-10-13 06:54:34.639798 | controller | skipping: Conditional result was False
2025-10-13 06:54:34.646073 | 
2025-10-13 06:54:34.646140 | TASK [ensure-pip : Ensure python3-venv]
2025-10-13 06:54:34.670271 | controller | skipping: Conditional result was False
2025-10-13 06:54:34.677054 | 
2025-10-13 06:54:34.677120 | TASK [ensure-pip : Install pip from source]
2025-10-13 06:54:34.691147 | controller | skipping: Conditional result was False
2025-10-13 06:54:34.697757 | 
2025-10-13 06:54:34.697824 | TASK [ensure-pip : Probe for venv python full path]
2025-10-13 02:54:34.965246 | controller | /usr/bin/python3
2025-10-13 06:54:35.235192 | controller | ok: Runtime: 0:00:00.005529
2025-10-13 06:54:35.241115 | 
2025-10-13 06:54:35.241180 | TASK [ensure-pip : Set host default]
2025-10-13 06:54:35.321926 | controller | ok
2025-10-13 06:54:35.327439 | 
2025-10-13 06:54:35.327503 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-10-13 06:54:35.433486 | controller | ok
2025-10-13 06:54:35.452001 | 
2025-10-13 06:54:35.452137 | TASK [bindep : Install bindep into temporary venv]
2025-10-13 06:54:39.623716 | controller | changed
2025-10-13 06:54:39.632295 | 
2025-10-13 06:54:39.632377 | TASK [bindep : Define bindep_command]
2025-10-13 06:54:39.665937 | controller | ok
2025-10-13 06:54:39.677442 | 
2025-10-13 06:54:39.677536 | LOOP [bindep : Include package tasks]
2025-10-13 06:54:39.733508 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-10-13 06:54:39.733693 | controller | ok: All items complete
2025-10-13 06:54:39.733722 | 
2025-10-13 06:54:39.748518 | controller | included: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-10-13 06:54:39.760328 | 
2025-10-13 06:54:39.760403 | TASK [bindep : Define bindep_run fact]
2025-10-13 06:54:39.790888 | controller | ok
2025-10-13 06:54:39.796093 | 
2025-10-13 06:54:39.796160 | TASK [bindep : Get list of packages to install from bindep]
2025-10-13 02:54:41.230475 | controller | podman
2025-10-13 02:54:41.269701 | controller | python3-jmespath
2025-10-13 02:54:41.269961 | controller | python3-libvirt
2025-10-13 02:54:41.269988 | controller | python3-lxml
2025-10-13 02:54:41.270002 | controller | python3-netaddr
2025-10-13 06:54:41.337543 | controller | ok: Runtime: 0:00:01.207652
2025-10-13 06:54:41.343331 | 
2025-10-13 06:54:41.343398 | TASK [bindep : Install distro packages from bindep]
2025-10-13 06:55:43.037586 | controller | changed
2025-10-13 06:55:43.050581 | 
2025-10-13 06:55:43.050753 | TASK [bindep : Check that packages are installed]
2025-10-13 06:55:44.597227 | controller | ok: Runtime: 0:00:01.042314
2025-10-13 06:55:44.610976 | 
2025-10-13 06:55:44.611137 | TASK [bindep : Fail if we cannot install all packages]
2025-10-13 06:55:44.649555 | controller | skipping: Conditional result was False
2025-10-13 06:55:44.674732 | 
2025-10-13 06:55:44.674940 | TASK [Run test-setup role]
2025-10-13 06:55:44.706989 | controller | ok
2025-10-13 06:55:44.737687 | 
2025-10-13 06:55:44.737831 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-13 06:55:44.990421 | controller | ok
2025-10-13 06:55:45.002752 | 
2025-10-13 06:55:45.002919 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-13 06:55:45.550958 | controller | skipping: Conditional result was False
2025-10-13 06:55:45.594797 | 
2025-10-13 06:55:45.594989 | TASK [bindep : Remove bindep temp dir]
2025-10-13 06:55:45.971843 | controller | ok
2025-10-13 06:55:45.994183 | 
2025-10-13 06:55:45.994291 | PLAY RECAP
2025-10-13 06:55:45.994375 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-10-13 06:55:45.994419 | 
2025-10-13 06:55:46.113482 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-13 06:55:46.115248 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-13 06:55:46.728625 | 
2025-10-13 06:55:46.728760 | PLAY [all]
2025-10-13 06:55:46.749865 | 
2025-10-13 06:55:46.749964 | TASK [Abort when test_command variable is undefined]
2025-10-13 06:55:46.785324 | controller | skipping: Conditional result was False
2025-10-13 06:55:46.790975 | 
2025-10-13 06:55:46.791049 | TASK [Convert test_command to list]
2025-10-13 06:55:46.825227 | controller | skipping: Conditional result was False
2025-10-13 06:55:46.834126 | 
2025-10-13 06:55:46.834214 | TASK [Use test_command list]
2025-10-13 06:55:46.889455 | controller | ok
2025-10-13 06:55:46.900935 | 
2025-10-13 06:55:46.901063 | LOOP [Run test_command]
2025-10-13 06:55:47.304640 | controller | no check to run
2025-10-13 06:55:47.305023 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.007034
2025-10-13 06:55:47.358736 | 
2025-10-13 06:55:47.358909 | PLAY RECAP
2025-10-13 06:55:47.358989 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-13 06:55:47.359034 | 
2025-10-13 06:55:47.467441 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-10-13 06:55:47.469222 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 06:55:48.118611 | 
2025-10-13 06:55:48.118745 | PLAY [all]
2025-10-13 06:55:48.139456 | 
2025-10-13 06:55:48.139541 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-13 06:55:48.507829 | controller | changed: non-zero return code
2025-10-13 06:55:48.519916 | 
2025-10-13 06:55:48.520076 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-13 06:55:48.547473 | controller | skipping: Conditional result was False
2025-10-13 06:55:48.562408 | 
2025-10-13 06:55:48.562635 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-13 06:55:48.601829 | 
2025-10-13 06:55:48.602135 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-13 06:55:48.642837 | 
2025-10-13 06:55:48.643036 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-13 06:55:48.668011 | controller | skipping: Conditional result was False
2025-10-13 06:55:48.681260 | 
2025-10-13 06:55:48.681418 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-13 06:55:48.722590 | 
2025-10-13 06:55:48.722950 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-13 06:55:48.755191 | controller | skipping: Conditional result was False
2025-10-13 06:55:48.770088 | 
2025-10-13 06:55:48.770284 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-13 06:55:48.799771 | controller | skipping: Conditional result was False
2025-10-13 06:55:48.814990 | 
2025-10-13 06:55:48.815158 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-13 06:55:48.844481 | controller | skipping: Conditional result was False
2025-10-13 06:55:48.897494 | 
2025-10-13 06:55:48.897685 | PLAY RECAP
2025-10-13 06:55:48.897761 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-13 06:55:48.897794 | 
2025-10-13 06:55:49.011540 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-13 06:55:49.012384 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-13 06:55:49.613492 | 
2025-10-13 06:55:49.613610 | PLAY [all]
2025-10-13 06:55:49.633481 | 
2025-10-13 06:55:49.633571 | TASK [include_role : fetch-output]
2025-10-13 06:55:49.676337 | controller | ok
2025-10-13 06:55:49.694082 | 
2025-10-13 06:55:49.694169 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-13 06:55:49.738595 | controller | skipping: Conditional result was False
2025-10-13 06:55:49.744285 | 
2025-10-13 06:55:49.744351 | TASK [fetch-output : Set log path for single node]
2025-10-13 06:55:49.772985 | controller | ok
2025-10-13 06:55:49.778190 | 
2025-10-13 06:55:49.778256 | LOOP [fetch-output : Ensure local output dirs]
2025-10-13 06:55:50.169043 | controller -> localhost | ok: "/var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/work/logs"
2025-10-13 06:55:50.362585 | controller -> localhost | changed: "/var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/work/artifacts"
2025-10-13 06:55:50.571061 | controller -> localhost | changed: "/var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/work/docs"
2025-10-13 06:55:50.583865 | 
2025-10-13 06:55:50.583981 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-13 06:55:51.228599 | controller | changed: .d..t...... ./
2025-10-13 06:55:51.228981 | controller | changed: All items complete
2025-10-13 06:55:51.229043 | 
2025-10-13 06:55:51.678947 | controller | changed: .d..t...... ./
2025-10-13 06:55:52.173079 | controller | changed: .d..t...... ./
2025-10-13 06:55:52.194287 | 
2025-10-13 06:55:52.194382 | TASK [include_role : fetch-output-openshift]
2025-10-13 06:55:52.242440 | controller | skipping: Conditional result was False
2025-10-13 06:55:52.255748 | 
2025-10-13 06:55:52.255851 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-13 06:55:52.691087 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.007644
2025-10-13 06:55:52.977706 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.008461
2025-10-13 06:55:53.009587 | 
2025-10-13 06:55:53.009697 | PLAY [all]
2025-10-13 06:55:53.024421 | 
2025-10-13 06:55:53.024485 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-10-13 06:55:53.463516 | controller | changed
2025-10-13 06:55:53.488868 | 
2025-10-13 06:55:53.488929 | PLAY RECAP
2025-10-13 06:55:53.488969 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-10-13 06:55:53.488989 | 
2025-10-13 06:55:53.587405 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-10-13 06:55:53.588338 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-10-13 06:55:54.189688 | 
2025-10-13 06:55:54.189802 | PLAY [localhost]
2025-10-13 06:55:54.207786 | 
2025-10-13 06:55:54.207862 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-13 06:55:54.566337 | localhost | changed
2025-10-13 06:55:54.576581 | 
2025-10-13 06:55:54.576775 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-13 06:55:54.602748 | localhost | ok
2025-10-13 06:55:54.611101 | 
2025-10-13 06:55:54.611171 | TASK [add-fileserver : Create SSH private key tempfile]
2025-10-13 06:55:54.991082 | localhost | changed
2025-10-13 06:55:55.001597 | 
2025-10-13 06:55:55.001718 | TASK [add-fileserver : Create SSH private key from secret]
2025-10-13 06:55:55.713612 | localhost | changed
2025-10-13 06:55:55.719334 | 
2025-10-13 06:55:55.719395 | TASK [add-fileserver : Add fileserver ssh key]
2025-10-13 06:55:56.124261 | localhost | Identity added: /var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/work/tmp/ansible.z95c2tcw (/var/lib/zuul/builds/86c35fae9e0041d69c7c1fe19708e36f/work/tmp/ansible.z95c2tcw)
2025-10-13 06:55:56.124450 | localhost | ok: Runtime: 0:00:00.008454
2025-10-13 06:55:56.128978 | 
2025-10-13 06:55:56.129043 | TASK [add-fileserver : Remove SSH private key from disk]
2025-10-13 06:55:56.363073 | localhost | ok: Runtime: 0:00:00.010766
2025-10-13 06:55:56.370461 | 
2025-10-13 06:55:56.370525 | TASK [add-fileserver : Add fileserver to inventory]
2025-10-13 06:55:56.422224 | localhost | changed
2025-10-13 06:55:56.427398 | 
2025-10-13 06:55:56.427461 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-10-13 06:55:56.800829 | localhost | changed
2025-10-13 06:55:56.825554 | 
2025-10-13 06:55:56.825646 | PLAY [localhost]
2025-10-13 06:55:56.838835 | 
2025-10-13 06:55:56.838903 | TASK [Generate bulk log download script]
2025-10-13 06:55:56.868021 | localhost | ok
2025-10-13 06:55:56.889794 | 
2025-10-13 06:55:56.889866 | TASK [local-log-download : Check API endpoint is defined]
2025-10-13 06:55:56.948197 | localhost | ok: All assertions passed
2025-10-13 06:55:56.953266 | 
2025-10-13 06:55:56.953348 | TASK [local-log-download : Create download script]
2025-10-13 06:55:57.458615 | localhost -> localhost | changed
2025-10-13 06:55:57.468061 | 
2025-10-13 06:55:57.468125 | TASK [Register quick-download link]
2025-10-13 06:55:57.521965 | localhost | ok
2025-10-13 06:55:57.600543 | 
2025-10-13 06:55:57.600641 | PLAY [logserver.rdoproject.org]
2025-10-13 06:55:57.618784 | 
2025-10-13 06:55:57.618897 | TASK [Set zuul-log-path fact]
2025-10-13 06:55:57.644795 | logserver.rdoproject.org | ok
2025-10-13 06:55:57.654127 | 
2025-10-13 06:55:57.654190 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-13 06:55:57.705762 | logserver.rdoproject.org | ok
2025-10-13 06:55:57.711390 | 
2025-10-13 06:55:57.711450 | TASK [upload-logs : Create log directories]
2025-10-13 06:55:58.466304 | logserver.rdoproject.org | changed
2025-10-13 06:55:58.470907 | 
2025-10-13 06:55:58.470975 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-10-13 06:55:58.895468 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.005936
2025-10-13 06:55:58.900386 | 
2025-10-13 06:55:58.900448 | TASK [upload-logs : Upload logs to log server]
2025-10-13 06:55:59.661147 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-10-13 06:55:59.664166 | 
2025-10-13 06:55:59.664226 | LOOP [upload-logs : Compress console log and json output]
2025-10-13 06:55:59.754430 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 06:55:59.777049 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 06:55:59.783968 | 
2025-10-13 06:55:59.784033 | LOOP [upload-logs : Upload compressed console log and json output]
2025-10-13 06:55:59.846574 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 06:55:59.846825 | 
2025-10-13 06:55:59.847317 | logserver.rdoproject.org | skipping: Conditional result was False
2025-10-13 06:55:59.851611 | 
2025-10-13 06:55:59.851697 | LOOP [upload-logs : Upload console log and json output]