2025-10-13 14:52:57.444639 | Job console starting... 2025-10-13 14:52:57.456513 | Updating repositories 2025-10-13 14:52:57.486483 | Preparing job workspace 2025-10-13 14:53:02.674938 | Running Ansible setup... 2025-10-13 14:53:07.792921 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-13 14:53:09.326952 | 2025-10-13 14:53:09.327093 | PLAY [localhost] 2025-10-13 14:53:09.342063 | 2025-10-13 14:53:09.342198 | TASK [Gathering Facts] 2025-10-13 14:53:11.634876 | localhost | ok 2025-10-13 14:53:11.659464 | 2025-10-13 14:53:11.659588 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-13 14:53:12.479140 | localhost -> localhost | changed 2025-10-13 14:53:12.484999 | 2025-10-13 14:53:12.485096 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-13 14:53:14.072265 | localhost -> localhost | changed 2025-10-13 14:53:14.093680 | 2025-10-13 14:53:14.093898 | TASK [Setup log path fact] 2025-10-13 14:53:14.138460 | localhost | ok 2025-10-13 14:53:14.174273 | 2025-10-13 14:53:14.174414 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-13 14:53:14.254259 | localhost | ok 2025-10-13 14:53:14.268966 | 2025-10-13 14:53:14.269102 | TASK [emit-job-header : Print job information] 2025-10-13 14:53:14.369052 | # Job Information 2025-10-13 14:53:14.369211 | Ansible Version: 2.15.12 2025-10-13 14:53:14.369237 | Job: cifmw-molecule-fix_python_encodings 2025-10-13 14:53:14.369258 | Pipeline: github-check 2025-10-13 14:53:14.369276 | Executor: ze03.softwarefactory-project.io 2025-10-13 14:53:14.369294 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3402 2025-10-13 14:53:14.369415 | Log URL (when completed): https://logserver.rdoproject.org/573/rdoproject.org/57327955556d4852a933b9498e535ff2/ 2025-10-13 14:53:14.369447 | Event ID: 03ccc7c0-a844-11f0-9fcd-d5792746e07c 2025-10-13 14:53:14.373544 | 2025-10-13 14:53:14.373607 | LOOP [emit-job-header : Print node information] 2025-10-13 14:53:14.604109 | localhost | ok: 2025-10-13 14:53:14.604294 | localhost | # Node Information 2025-10-13 14:53:14.604324 | localhost | Inventory Hostname: controller 2025-10-13 14:53:14.604350 | localhost | Hostname: np0005485327 2025-10-13 14:53:14.604370 | localhost | Username: zuul 2025-10-13 14:53:14.604393 | localhost | Distro: CentOS 9 2025-10-13 14:53:14.604416 | localhost | Provider: vexxhost-nodepool-tripleo 2025-10-13 14:53:14.604439 | localhost | Region: RegionOne 2025-10-13 14:53:14.604464 | localhost | Label: cloud-centos-9-stream-tripleo 2025-10-13 14:53:14.604485 | localhost | Product Name: OpenStack Nova 2025-10-13 14:53:14.604504 | localhost | Interface IP: 38.129.56.117 2025-10-13 14:53:14.649326 | 2025-10-13 14:53:14.649448 | PLAY [all] 2025-10-13 14:53:14.666333 | 2025-10-13 14:53:14.666446 | TASK [Gather network facts] 2025-10-13 14:53:15.139668 | controller | ok 2025-10-13 14:53:15.158641 | 2025-10-13 14:53:15.158847 | TASK [include_role : start-zuul-console] 2025-10-13 14:53:15.179121 | controller | ok 2025-10-13 14:53:15.193812 | 2025-10-13 14:53:15.193938 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-13 14:53:15.759542 | controller | ok 2025-10-13 14:53:15.776222 | 2025-10-13 14:53:15.776343 | TASK [include_role : add-build-sshkey] 2025-10-13 14:53:15.830484 | controller | ok 2025-10-13 14:53:15.873347 | 2025-10-13 14:53:15.873460 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-13 14:53:16.468498 | controller -> localhost | ok 2025-10-13 14:53:16.474068 | 2025-10-13 14:53:16.474129 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-13 14:53:16.534307 | controller | ok 2025-10-13 14:53:16.579311 | controller | included: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-13 14:53:16.605365 | 2025-10-13 14:53:16.605488 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-13 14:53:17.658872 | controller -> localhost | Generating public/private rsa key pair. 2025-10-13 14:53:17.659103 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/work/57327955556d4852a933b9498e535ff2_id_rsa. 2025-10-13 14:53:17.659136 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/work/57327955556d4852a933b9498e535ff2_id_rsa.pub. 2025-10-13 14:53:17.659167 | controller -> localhost | The key fingerprint is: 2025-10-13 14:53:17.659196 | controller -> localhost | SHA256:5jmbOJEh0mnyZ1UbihmvMhWO1F76dmgsmWtN+lzusIs zuul-build-sshkey 2025-10-13 14:53:17.659220 | controller -> localhost | The key's randomart image is: 2025-10-13 14:53:17.659239 | controller -> localhost | +---[RSA 3072]----+ 2025-10-13 14:53:17.659257 | controller -> localhost | | . | 2025-10-13 14:53:17.659276 | controller -> localhost | | . + . o | 2025-10-13 14:53:17.659293 | controller -> localhost | | o = O o o | 2025-10-13 14:53:17.659312 | controller -> localhost | | o * O + . | 2025-10-13 14:53:17.659329 | controller -> localhost | | = o XS. | 2025-10-13 14:53:17.659347 | controller -> localhost | | + XoB.. | 2025-10-13 14:53:17.659364 | controller -> localhost | | = X=.. | 2025-10-13 14:53:17.659382 | controller -> localhost | | =+.O | 2025-10-13 14:53:17.659399 | controller -> localhost | | .EoBoo | 2025-10-13 14:53:17.659417 | controller -> localhost | +----[SHA256]-----+ 2025-10-13 14:53:17.659462 | controller -> localhost | ok: Runtime: 0:00:00.289988 2025-10-13 14:53:17.665640 | 2025-10-13 14:53:17.665710 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-13 14:53:17.696669 | controller | ok 2025-10-13 14:53:17.706994 | controller | included: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-13 14:53:17.717269 | 2025-10-13 14:53:17.717399 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-13 14:53:17.742769 | controller | skipping: Conditional result was False 2025-10-13 14:53:17.750007 | 2025-10-13 14:53:17.750151 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-13 14:53:18.315308 | controller | changed 2025-10-13 14:53:18.331796 | 2025-10-13 14:53:18.331910 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-13 14:53:18.593628 | controller | ok 2025-10-13 14:53:18.598922 | 2025-10-13 14:53:18.599017 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-13 14:53:19.631436 | controller | changed 2025-10-13 14:53:19.636918 | 2025-10-13 14:53:19.636993 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-13 14:53:20.622981 | controller | changed 2025-10-13 14:53:20.632612 | 2025-10-13 14:53:20.632702 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-13 14:53:20.656991 | controller | skipping: Conditional result was False 2025-10-13 14:53:20.662825 | 2025-10-13 14:53:20.662919 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-13 14:53:21.161916 | controller -> localhost | changed 2025-10-13 14:53:21.172875 | 2025-10-13 14:53:21.172957 | TASK [add-build-sshkey : Add back temp key] 2025-10-13 14:53:21.431371 | controller -> localhost | Identity added: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/work/57327955556d4852a933b9498e535ff2_id_rsa (zuul-build-sshkey) 2025-10-13 14:53:21.431566 | controller -> localhost | ok: Runtime: 0:00:00.009692 2025-10-13 14:53:21.437369 | 2025-10-13 14:53:21.437436 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-13 14:53:21.854210 | controller | ok 2025-10-13 14:53:21.916122 | 2025-10-13 14:53:21.916239 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-13 14:53:21.951118 | controller | skipping: Conditional result was False 2025-10-13 14:53:21.965930 | 2025-10-13 14:53:21.966026 | TASK [include_role : validate-host] 2025-10-13 14:53:21.988383 | controller | ok 2025-10-13 14:53:22.009617 | 2025-10-13 14:53:22.009788 | TASK [validate-host : Define zuul_info_dir fact] 2025-10-13 14:53:22.048599 | controller | ok 2025-10-13 14:53:22.053808 | 2025-10-13 14:53:22.053866 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-10-13 14:53:22.317232 | controller -> localhost | ok 2025-10-13 14:53:22.323719 | 2025-10-13 14:53:22.323845 | TASK [validate-host : Collect information about the host] 2025-10-13 14:53:23.084021 | controller | ok 2025-10-13 14:53:23.094084 | 2025-10-13 14:53:23.094189 | TASK [validate-host : Sanitize hostname] 2025-10-13 14:53:23.186578 | controller | ok 2025-10-13 14:53:23.191901 | 2025-10-13 14:53:23.191991 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-10-13 14:53:23.906310 | controller -> localhost | changed 2025-10-13 14:53:23.912645 | 2025-10-13 14:53:23.912802 | TASK [validate-host : Collect information about zuul worker] 2025-10-13 14:53:24.389387 | controller | ok 2025-10-13 14:53:24.394705 | 2025-10-13 14:53:24.394848 | TASK [validate-host : Write out all zuul information for each host] 2025-10-13 14:53:24.889972 | controller -> localhost | changed 2025-10-13 14:53:24.900059 | 2025-10-13 14:53:24.900124 | TASK [include_role : prepare-workspace-openshift] 2025-10-13 14:53:24.923986 | controller | skipping: Conditional result was False 2025-10-13 14:53:24.929697 | 2025-10-13 14:53:24.929937 | TASK [include_role : remove-zuul-sshkey] 2025-10-13 14:53:24.964296 | controller | skipping: Conditional result was False 2025-10-13 14:53:24.974288 | 2025-10-13 14:53:24.974432 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-13 14:53:25.217549 | controller | ok: "logs" 2025-10-13 14:53:25.217792 | controller | ok: All items complete 2025-10-13 14:53:25.217821 | 2025-10-13 14:53:25.469524 | controller | ok: "artifacts" 2025-10-13 14:53:25.772003 | controller | ok: "docs" 2025-10-13 14:53:25.801899 | 2025-10-13 14:53:25.802194 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-13 14:53:26.111034 | controller | changed: "logs" 2025-10-13 14:53:26.349164 | controller | changed: "artifacts" 2025-10-13 14:53:26.593238 | controller | changed: "docs" 2025-10-13 14:53:26.633622 | 2025-10-13 14:53:26.633715 | PLAY RECAP 2025-10-13 14:53:26.633780 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-13 14:53:26.633808 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-13 14:53:26.633827 | 2025-10-13 14:53:26.764636 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-13 14:53:26.765514 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-13 14:53:27.484777 | 2025-10-13 14:53:27.484905 | PLAY [localhost] 2025-10-13 14:53:27.501937 | 2025-10-13 14:53:27.502055 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-10-13 14:53:27.928866 | localhost | ok 2025-10-13 14:53:27.934164 | 2025-10-13 14:53:27.934281 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-10-13 14:53:28.698976 | localhost | changed 2025-10-13 14:53:28.720926 | 2025-10-13 14:53:28.721011 | PLAY [all] 2025-10-13 14:53:28.737149 | 2025-10-13 14:53:28.737221 | TASK [include_role : prepare-workspace] 2025-10-13 14:53:28.756590 | controller | ok 2025-10-13 14:53:28.770671 | 2025-10-13 14:53:28.770770 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-13 14:53:29.175665 | controller | ok 2025-10-13 14:53:29.192902 | 2025-10-13 14:53:29.192994 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-13 14:53:30.882531 | controller | Output suppressed because no_log was given 2025-10-13 14:53:30.899799 | 2025-10-13 14:53:30.900028 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-13 14:53:31.197090 | controller | changed: "logs" 2025-10-13 14:53:31.419989 | controller | changed: "artifacts" 2025-10-13 14:53:31.634963 | controller | changed: "docs" 2025-10-13 14:53:31.647275 | 2025-10-13 14:53:31.647461 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-13 14:53:31.989305 | controller | changed: "logs" 2025-10-13 14:53:31.994227 | controller | changed: All items complete 2025-10-13 14:53:31.994325 | 2025-10-13 14:53:32.207706 | controller | changed: "artifacts" 2025-10-13 14:53:32.438669 | controller | changed: "docs" 2025-10-13 14:53:32.470852 | 2025-10-13 14:53:32.471003 | TASK [Check if worker can sudo] 2025-10-13 14:53:33.527973 | controller | ok: Runtime: 0:00:00.042542 2025-10-13 14:53:33.534826 | 2025-10-13 14:53:33.534923 | TASK [configure-mirrors : Gather needed facts] 2025-10-13 14:53:33.690211 | controller | skipping: Conditional result was False 2025-10-13 14:53:33.696595 | 2025-10-13 14:53:33.696715 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-10-13 14:53:33.761024 | controller | ok 2025-10-13 14:53:33.773776 | controller | included: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-10-13 14:53:33.818480 | 2025-10-13 14:53:33.818600 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-10-13 14:53:34.149207 | controller | ok 2025-10-13 14:53:34.160632 | 2025-10-13 14:53:34.160719 | LOOP [configure-mirrors : Include OS-specific variables] 2025-10-13 14:53:34.373683 | controller | ok: "/var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-10-13 14:53:34.387540 | 2025-10-13 14:53:34.387659 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-10-13 14:53:35.288403 | controller | changed 2025-10-13 14:53:35.294909 | 2025-10-13 14:53:35.295582 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-10-13 14:53:35.441351 | controller | ok: "/var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-10-13 14:53:35.441632 | controller | ok: All items complete 2025-10-13 14:53:35.441673 | 2025-10-13 14:53:35.494300 | controller | included: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-10-13 14:53:35.510932 | 2025-10-13 14:53:35.511119 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-10-13 14:53:36.538709 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-10-13 14:53:37.392357 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-10-13 14:53:37.406663 | 2025-10-13 14:53:37.406832 | TASK [configure-mirrors : Disable deltrarpm] 2025-10-13 14:53:38.109487 | controller | changed: section and option added 2025-10-13 14:53:38.159333 | 2025-10-13 14:53:38.159478 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-10-13 14:53:39.033742 | controller | 29 files removed 2025-10-13 14:53:39.034026 | controller | ok: Item: dnf clean all Runtime: 0:00:00.534818 2025-10-13 14:53:39.034081 | controller | changed: All items complete 2025-10-13 14:53:39.034112 | 2025-10-13 14:53:50.282590 | 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 14:53:50.286303 | controller | DNF version: 4.14.0 2025-10-13 14:53:50.286391 | controller | cachedir: /var/cache/dnf 2025-10-13 14:53:50.286420 | controller | Making cache files for all metadata files. 2025-10-13 14:53:50.286444 | controller | baseos: has expired and will be refreshed. 2025-10-13 14:53:50.286466 | controller | appstream: has expired and will be refreshed. 2025-10-13 14:53:50.286488 | controller | crb: has expired and will be refreshed. 2025-10-13 14:53:50.286646 | controller | extras-common: has expired and will be refreshed. 2025-10-13 14:53:50.286681 | controller | repo: downloading from remote: baseos 2025-10-13 14:53:50.286705 | controller | CentOS Stream 9 - BaseOS 51 MB/s | 8.8 MB 00:00 2025-10-13 14:53:50.286751 | controller | baseos: using metadata from Wed 08 Oct 2025 09:42:12 AM EDT. 2025-10-13 14:53:50.286775 | controller | repo: downloading from remote: appstream 2025-10-13 14:53:50.286798 | controller | CentOS Stream 9 - AppStream 52 MB/s | 25 MB 00:00 2025-10-13 14:53:50.286819 | controller | appstream: using metadata from Wed 08 Oct 2025 09:45:45 AM EDT. 2025-10-13 14:53:50.286842 | controller | repo: downloading from remote: crb 2025-10-13 14:53:50.286865 | controller | CentOS Stream 9 - CRB 63 MB/s | 7.2 MB 00:00 2025-10-13 14:53:50.286889 | controller | crb: using metadata from Wed 08 Oct 2025 09:50:07 AM EDT. 2025-10-13 14:53:50.286913 | controller | repo: downloading from remote: extras-common 2025-10-13 14:53:50.286937 | controller | CentOS Stream 9 - Extras packages 1.3 MB/s | 20 kB 00:00 2025-10-13 14:53:50.286962 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-10-13 14:53:50.286986 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-10-13 14:53:50.287010 | controller | Completion plugin: Generating completion cache... 2025-10-13 14:53:50.287035 | controller | Metadata cache created. 2025-10-13 14:53:50.287083 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.996803 2025-10-13 14:53:50.310387 | 2025-10-13 14:53:50.310477 | PLAY RECAP 2025-10-13 14:53:50.310518 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-13 14:53:50.310544 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-13 14:53:50.310562 | 2025-10-13 14:53:50.430902 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-13 14:53:50.431804 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-13 14:53:51.062010 | 2025-10-13 14:53:51.062148 | PLAY [all] 2025-10-13 14:53:51.083942 | 2025-10-13 14:53:51.084068 | TASK [Install binary dependencies] 2025-10-13 14:53:51.143565 | controller | ok 2025-10-13 14:53:51.163049 | 2025-10-13 14:53:51.163179 | TASK [bindep : Include find tasks] 2025-10-13 14:53:51.193449 | controller | ok 2025-10-13 14:53:51.201056 | controller | included: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-13 14:53:51.207468 | 2025-10-13 14:53:51.207538 | TASK [bindep : Look for bindep.txt] 2025-10-13 14:53:51.612842 | controller | ok 2025-10-13 14:53:51.628176 | 2025-10-13 14:53:51.628353 | TASK [bindep : Define bindep_file fact] 2025-10-13 14:53:51.668563 | controller | ok 2025-10-13 14:53:51.677950 | 2025-10-13 14:53:51.678051 | TASK [bindep : Look for other-requirements.txt] 2025-10-13 14:53:51.693481 | controller | skipping: Conditional result was False 2025-10-13 14:53:51.700978 | 2025-10-13 14:53:51.701130 | TASK [bindep : Define bindep_file fact] 2025-10-13 14:53:51.726562 | controller | skipping: Conditional result was False 2025-10-13 14:53:51.733083 | 2025-10-13 14:53:51.733188 | TASK [bindep : Look for bindep fallback file] 2025-10-13 14:53:51.757632 | controller | skipping: Conditional result was False 2025-10-13 14:53:51.763748 | 2025-10-13 14:53:51.763866 | TASK [bindep : Define bindep_file fact] 2025-10-13 14:53:51.789253 | controller | skipping: Conditional result was False 2025-10-13 14:53:51.797124 | 2025-10-13 14:53:51.797286 | TASK [bindep : Include bindep tasks] 2025-10-13 14:53:51.833129 | controller | ok 2025-10-13 14:53:51.840415 | controller | included: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-10-13 14:53:51.849342 | 2025-10-13 14:53:51.849426 | TASK [bindep : Look for bindep command] 2025-10-13 14:53:51.884134 | controller | skipping: Conditional result was False 2025-10-13 14:53:51.895248 | 2025-10-13 14:53:51.895396 | TASK [bindep : Check for system bindep] 2025-10-13 14:53:52.439525 | controller | ok: Runtime: 0:00:00.007060 2025-10-13 14:53:52.450119 | 2025-10-13 14:53:52.450250 | TASK [bindep : Define bindep_command fact] 2025-10-13 14:53:52.486606 | controller | skipping: Conditional result was False 2025-10-13 14:53:52.492767 | 2025-10-13 14:53:52.492868 | TASK [bindep : Include install tasks] 2025-10-13 14:53:52.527176 | controller | ok 2025-10-13 14:53:52.541588 | controller | included: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-10-13 14:53:52.558640 | 2025-10-13 14:53:52.558908 | TASK [bindep : Create temp dir for bindep] 2025-10-13 14:53:52.992273 | controller | changed 2025-10-13 14:53:52.999812 | 2025-10-13 14:53:52.999900 | TASK [Ensure we have pip dependencies] 2025-10-13 14:53:53.033110 | controller | ok 2025-10-13 14:53:53.066408 | 2025-10-13 14:53:53.066531 | TASK [ensure-pip : Check if pip is installed] 2025-10-13 10:53:53.346218 | controller | /usr/bin/pip3 2025-10-13 10:53:53.366651 | controller | /usr/bin/python3: No module named wheel 2025-10-13 14:53:53.597282 | controller | ok: Runtime: 0:00:00.029461 2025-10-13 14:53:53.611878 | 2025-10-13 14:53:53.612107 | LOOP [ensure-pip : Install pip from packages] 2025-10-13 14:53:53.664208 | controller | ok: "/var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-10-13 14:53:53.688806 | controller | included: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-10-13 14:53:53.709660 | 2025-10-13 14:53:53.709968 | TASK [ensure-pip : Install Python 3 pip] 2025-10-13 14:53:56.121266 | controller | changed 2025-10-13 14:53:56.127233 | 2025-10-13 14:53:56.127328 | TASK [ensure-pip : Check for EPEL repository] 2025-10-13 14:53:56.162347 | controller | skipping: Conditional result was False 2025-10-13 14:53:56.169784 | 2025-10-13 14:53:56.169923 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-10-13 14:53:56.205155 | controller | skipping: Conditional result was False 2025-10-13 14:53:56.214493 | 2025-10-13 14:53:56.214606 | TASK [ensure-pip : Install Python 2 pip] 2025-10-13 14:53:56.279957 | controller | skipping: Conditional result was False 2025-10-13 14:53:56.289064 | 2025-10-13 14:53:56.289161 | TASK [ensure-pip : Ensure setuptools] 2025-10-13 14:53:56.314864 | controller | skipping: Conditional result was False 2025-10-13 14:53:56.328855 | 2025-10-13 14:53:56.329045 | TASK [ensure-pip : Check for ensurepip module] 2025-10-13 14:53:56.874589 | controller | skipping: Conditional result was False 2025-10-13 14:53:56.883257 | 2025-10-13 14:53:56.883380 | TASK [ensure-pip : Ensure python3-venv] 2025-10-13 14:53:56.908682 | controller | skipping: Conditional result was False 2025-10-13 14:53:56.916900 | 2025-10-13 14:53:56.917041 | TASK [ensure-pip : Install pip from source] 2025-10-13 14:53:56.942208 | controller | skipping: Conditional result was False 2025-10-13 14:53:56.950616 | 2025-10-13 14:53:56.950777 | TASK [ensure-pip : Probe for venv python full path] 2025-10-13 10:53:57.198330 | controller | /usr/bin/python3 2025-10-13 14:53:57.481353 | controller | ok: Runtime: 0:00:00.005402 2025-10-13 14:53:57.487656 | 2025-10-13 14:53:57.487806 | TASK [ensure-pip : Set host default] 2025-10-13 14:53:57.538323 | controller | ok 2025-10-13 14:53:57.543630 | 2025-10-13 14:53:57.543711 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-10-13 14:53:57.594495 | controller | ok 2025-10-13 14:53:57.610054 | 2025-10-13 14:53:57.610188 | TASK [bindep : Install bindep into temporary venv] 2025-10-13 14:54:01.968357 | controller | changed 2025-10-13 14:54:01.985120 | 2025-10-13 14:54:01.985283 | TASK [bindep : Define bindep_command] 2025-10-13 14:54:02.030720 | controller | ok 2025-10-13 14:54:02.039507 | 2025-10-13 14:54:02.039619 | LOOP [bindep : Include package tasks] 2025-10-13 14:54:02.090109 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-10-13 14:54:02.090694 | controller | ok: All items complete 2025-10-13 14:54:02.090771 | 2025-10-13 14:54:02.112941 | controller | included: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-10-13 14:54:02.130593 | 2025-10-13 14:54:02.130774 | TASK [bindep : Define bindep_run fact] 2025-10-13 14:54:02.163824 | controller | ok 2025-10-13 14:54:02.171763 | 2025-10-13 14:54:02.171858 | TASK [bindep : Get list of packages to install from bindep] 2025-10-13 10:54:03.566998 | controller | podman 2025-10-13 10:54:03.604133 | controller | python3-jmespath 2025-10-13 10:54:03.604279 | controller | python3-libvirt 2025-10-13 10:54:03.604289 | controller | python3-lxml 2025-10-13 10:54:03.604299 | controller | python3-netaddr 2025-10-13 14:54:03.712660 | controller | ok: Runtime: 0:00:01.176010 2025-10-13 14:54:03.721987 | 2025-10-13 14:54:03.722123 | TASK [bindep : Install distro packages from bindep] 2025-10-13 14:55:09.305329 | controller | changed 2025-10-13 14:55:09.314111 | 2025-10-13 14:55:09.314228 | TASK [bindep : Check that packages are installed] 2025-10-13 14:55:11.358749 | controller | ok: Runtime: 0:00:01.618657 2025-10-13 14:55:11.364831 | 2025-10-13 14:55:11.364915 | TASK [bindep : Fail if we cannot install all packages] 2025-10-13 14:55:11.396400 | controller | skipping: Conditional result was False 2025-10-13 14:55:11.407952 | 2025-10-13 14:55:11.408057 | TASK [Run test-setup role] 2025-10-13 14:55:11.442571 | controller | ok 2025-10-13 14:55:11.469940 | 2025-10-13 14:55:11.470038 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-13 14:55:11.772865 | controller | ok 2025-10-13 14:55:11.782350 | 2025-10-13 14:55:11.782477 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-13 14:55:12.321301 | controller | skipping: Conditional result was False 2025-10-13 14:55:12.350312 | 2025-10-13 14:55:12.350450 | TASK [bindep : Remove bindep temp dir] 2025-10-13 14:55:12.972791 | controller | ok 2025-10-13 14:55:12.992142 | 2025-10-13 14:55:12.992247 | PLAY RECAP 2025-10-13 14:55:12.992295 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-10-13 14:55:12.992317 | 2025-10-13 14:55:13.118906 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-13 14:55:13.119768 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-13 14:55:13.910132 | 2025-10-13 14:55:13.910290 | PLAY [all] 2025-10-13 14:55:13.931719 | 2025-10-13 14:55:13.931880 | TASK [Abort when test_command variable is undefined] 2025-10-13 14:55:13.966697 | controller | skipping: Conditional result was False 2025-10-13 14:55:13.972336 | 2025-10-13 14:55:13.972412 | TASK [Convert test_command to list] 2025-10-13 14:55:14.017694 | controller | skipping: Conditional result was False 2025-10-13 14:55:14.024468 | 2025-10-13 14:55:14.024545 | TASK [Use test_command list] 2025-10-13 14:55:14.075562 | controller | ok 2025-10-13 14:55:14.080780 | 2025-10-13 14:55:14.080838 | LOOP [Run test_command] 2025-10-13 14:55:14.559494 | controller | no check to run 2025-10-13 14:55:14.559671 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.006533 2025-10-13 14:55:14.608051 | 2025-10-13 14:55:14.608185 | PLAY RECAP 2025-10-13 14:55:14.608236 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-13 14:55:14.608258 | 2025-10-13 14:55:14.903747 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-13 14:55:14.904666 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-13 14:55:16.064036 | 2025-10-13 14:55:16.064287 | PLAY [all] 2025-10-13 14:55:16.087526 | 2025-10-13 14:55:16.087664 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-13 14:55:16.508638 | controller | changed: non-zero return code 2025-10-13 14:55:16.518176 | 2025-10-13 14:55:16.518287 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-13 14:55:16.534935 | controller | skipping: Conditional result was False 2025-10-13 14:55:16.542130 | 2025-10-13 14:55:16.542313 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-13 14:55:16.573368 | 2025-10-13 14:55:16.573573 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-13 14:55:16.604345 | 2025-10-13 14:55:16.604511 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-13 14:55:16.618571 | controller | skipping: Conditional result was False 2025-10-13 14:55:16.626036 | 2025-10-13 14:55:16.626166 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-13 14:55:16.652006 | 2025-10-13 14:55:16.652496 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-13 14:55:16.674148 | controller | skipping: Conditional result was False 2025-10-13 14:55:16.681283 | 2025-10-13 14:55:16.681386 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-13 14:55:16.697126 | controller | skipping: Conditional result was False 2025-10-13 14:55:16.704137 | 2025-10-13 14:55:16.704226 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-13 14:55:16.720932 | controller | skipping: Conditional result was False 2025-10-13 14:55:16.754031 | 2025-10-13 14:55:16.754148 | PLAY RECAP 2025-10-13 14:55:16.754201 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-13 14:55:16.754228 | 2025-10-13 14:55:16.869477 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-13 14:55:16.870330 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-13 14:55:17.662806 | 2025-10-13 14:55:17.662934 | PLAY [all] 2025-10-13 14:55:17.682708 | 2025-10-13 14:55:17.682870 | TASK [include_role : fetch-output] 2025-10-13 14:55:17.732853 | controller | ok 2025-10-13 14:55:17.753191 | 2025-10-13 14:55:17.753328 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-13 14:55:17.808197 | controller | skipping: Conditional result was False 2025-10-13 14:55:17.814972 | 2025-10-13 14:55:17.815085 | TASK [fetch-output : Set log path for single node] 2025-10-13 14:55:17.887534 | controller | ok 2025-10-13 14:55:17.893418 | 2025-10-13 14:55:17.893526 | LOOP [fetch-output : Ensure local output dirs] 2025-10-13 14:55:18.358203 | controller -> localhost | ok: "/var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/work/logs" 2025-10-13 14:55:18.838120 | controller -> localhost | changed: "/var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/work/artifacts" 2025-10-13 14:55:19.448313 | controller -> localhost | changed: "/var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/work/docs" 2025-10-13 14:55:19.461537 | 2025-10-13 14:55:19.461660 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-13 14:55:20.634656 | controller | changed: .d..t...... ./ 2025-10-13 14:55:20.634937 | controller | changed: All items complete 2025-10-13 14:55:20.634971 | 2025-10-13 14:55:21.522934 | controller | changed: .d..t...... ./ 2025-10-13 14:55:22.036230 | controller | changed: .d..t...... ./ 2025-10-13 14:55:22.054537 | 2025-10-13 14:55:22.054658 | TASK [include_role : fetch-output-openshift] 2025-10-13 14:55:22.091146 | controller | skipping: Conditional result was False 2025-10-13 14:55:22.133044 | 2025-10-13 14:55:22.133194 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-13 14:55:22.852760 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.024371 2025-10-13 14:55:23.177659 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.011896 2025-10-13 14:55:23.237009 | 2025-10-13 14:55:23.237106 | PLAY [all] 2025-10-13 14:55:23.260813 | 2025-10-13 14:55:23.260945 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-10-13 14:55:23.762069 | controller | changed 2025-10-13 14:55:23.821533 | 2025-10-13 14:55:23.821632 | PLAY RECAP 2025-10-13 14:55:23.821677 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-13 14:55:23.821698 | 2025-10-13 14:55:24.177319 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-13 14:55:24.178408 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-10-13 14:55:25.519331 | 2025-10-13 14:55:25.519460 | PLAY [localhost] 2025-10-13 14:55:25.543618 | 2025-10-13 14:55:25.543788 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-13 14:55:26.177667 | localhost | changed 2025-10-13 14:55:26.191059 | 2025-10-13 14:55:26.191190 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-13 14:55:26.237971 | localhost | ok 2025-10-13 14:55:26.254223 | 2025-10-13 14:55:26.254362 | TASK [add-fileserver : Create SSH private key tempfile] 2025-10-13 14:55:27.380605 | localhost | changed 2025-10-13 14:55:27.387496 | 2025-10-13 14:55:27.387627 | TASK [add-fileserver : Create SSH private key from secret] 2025-10-13 14:55:28.866914 | localhost | changed 2025-10-13 14:55:28.876502 | 2025-10-13 14:55:28.876644 | TASK [add-fileserver : Add fileserver ssh key] 2025-10-13 14:55:29.320833 | localhost | Identity added: /var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/work/tmp/ansible.8gkrdtfr (/var/lib/zuul/builds/57327955556d4852a933b9498e535ff2/work/tmp/ansible.8gkrdtfr) 2025-10-13 14:55:29.321063 | localhost | ok: Runtime: 0:00:00.012209 2025-10-13 14:55:29.330129 | 2025-10-13 14:55:29.330224 | TASK [add-fileserver : Remove SSH private key from disk] 2025-10-13 14:55:29.619327 | localhost | ok: Runtime: 0:00:00.005702 2025-10-13 14:55:29.626432 | 2025-10-13 14:55:29.626509 | TASK [add-fileserver : Add fileserver to inventory] 2025-10-13 14:55:29.686172 | localhost | changed 2025-10-13 14:55:29.691856 | 2025-10-13 14:55:29.691972 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-10-13 14:55:30.313870 | localhost | changed 2025-10-13 14:55:30.373240 | 2025-10-13 14:55:30.373340 | PLAY [localhost] 2025-10-13 14:55:30.391755 | 2025-10-13 14:55:30.391907 | TASK [Generate bulk log download script] 2025-10-13 14:55:30.421957 | localhost | ok 2025-10-13 14:55:30.434430 | 2025-10-13 14:55:30.434513 | TASK [local-log-download : Check API endpoint is defined] 2025-10-13 14:55:30.462123 | localhost | ok: All assertions passed 2025-10-13 14:55:30.467831 | 2025-10-13 14:55:30.467897 | TASK [local-log-download : Create download script] 2025-10-13 14:55:31.102555 | localhost -> localhost | changed 2025-10-13 14:55:31.111638 | 2025-10-13 14:55:31.111741 | TASK [Register quick-download link] 2025-10-13 14:55:31.132065 | localhost | ok 2025-10-13 14:55:31.149642 | 2025-10-13 14:55:31.149765 | PLAY [logserver.rdoproject.org] 2025-10-13 14:55:31.160501 | 2025-10-13 14:55:31.160599 | TASK [Set zuul-log-path fact] 2025-10-13 14:55:31.178675 | logserver.rdoproject.org | ok 2025-10-13 14:55:31.189359 | 2025-10-13 14:55:31.189474 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-13 14:55:31.217614 | logserver.rdoproject.org | ok 2025-10-13 14:55:31.240257 | 2025-10-13 14:55:31.240444 | TASK [upload-logs : Create log directories] 2025-10-13 14:55:32.049325 | logserver.rdoproject.org | changed 2025-10-13 14:55:32.054183 | 2025-10-13 14:55:32.054272 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-10-13 14:55:32.387330 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.010438 2025-10-13 14:55:32.392814 | 2025-10-13 14:55:32.392916 | TASK [upload-logs : Upload logs to log server] 2025-10-13 14:55:33.343010 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-10-13 14:55:33.351307 | 2025-10-13 14:55:33.351412 | LOOP [upload-logs : Compress console log and json output] 2025-10-13 14:55:33.432657 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 14:55:33.444550 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 14:55:33.451446 | 2025-10-13 14:55:33.451554 | LOOP [upload-logs : Upload compressed console log and json output] 2025-10-13 14:55:33.509369 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 14:55:33.509607 | 2025-10-13 14:55:33.510261 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 14:55:33.525153 | 2025-10-13 14:55:33.525272 | LOOP [upload-logs : Upload console log and json output]