2025-09-30 05:00:15.985077 | Job console starting...
2025-09-30 05:00:15.997886 | Updating repositories
2025-09-30 05:00:16.025153 | Preparing job workspace
2025-09-30 05:00:20.576629 | Running Ansible setup...
2025-09-30 05:00:24.399407 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 05:00:24.993308 | 
2025-09-30 05:00:24.993412 | PLAY [localhost]
2025-09-30 05:00:25.002675 | 
2025-09-30 05:00:25.002775 | TASK [Gathering Facts]
2025-09-30 05:00:25.946532 | localhost | ok
2025-09-30 05:00:25.961178 | 
2025-09-30 05:00:25.961304 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-30 05:00:26.301890 | localhost -> localhost | changed
2025-09-30 05:00:26.309983 | 
2025-09-30 05:00:26.310106 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-30 05:00:27.123815 | localhost -> localhost | changed
2025-09-30 05:00:27.136900 | 
2025-09-30 05:00:27.137018 | TASK [Setup log path fact]
2025-09-30 05:00:27.156900 | localhost | ok
2025-09-30 05:00:27.173027 | 
2025-09-30 05:00:27.173175 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 05:00:27.202968 | localhost | ok
2025-09-30 05:00:27.218775 | 
2025-09-30 05:00:27.218885 | TASK [emit-job-header : Print job information]
2025-09-30 05:00:27.259305 | # Job Information
2025-09-30 05:00:27.259493 | Ansible Version: 2.15.12
2025-09-30 05:00:27.259531 | Job: cifmw-molecule-ci_lvms_storage
2025-09-30 05:00:27.259562 | Pipeline: github-check
2025-09-30 05:00:27.259589 | Executor: ze03.softwarefactory-project.io
2025-09-30 05:00:27.259615 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333
2025-09-30 05:00:27.259643 | Log URL (when completed): https://logserver.rdoproject.org/799/rdoproject.org/799f6515b14e4a6fbd7fa21fb344a34d/
2025-09-30 05:00:27.259670 | Event ID: 3089cae0-9dba-11f0-9d66-59f03df1d747
2025-09-30 05:00:27.265276 | 
2025-09-30 05:00:27.265405 | LOOP [emit-job-header : Print node information]
2025-09-30 05:00:27.370294 | localhost | ok:
2025-09-30 05:00:27.370837 | localhost | # Node Information
2025-09-30 05:00:27.382941 | localhost | Inventory Hostname: controller
2025-09-30 05:00:27.383003 | localhost | Hostname: np0005461544
2025-09-30 05:00:27.383037 | localhost | Username: zuul
2025-09-30 05:00:27.383070 | localhost | Distro: CentOS 9
2025-09-30 05:00:27.383100 | localhost | Provider: vexxhost-nodepool-tripleo
2025-09-30 05:00:27.383128 | localhost | Region: RegionOne
2025-09-30 05:00:27.383156 | localhost | Label: cloud-centos-9-stream-tripleo
2025-09-30 05:00:27.383182 | localhost | Product Name: OpenStack Nova
2025-09-30 05:00:27.383209 | localhost | Interface IP: 38.102.83.80
2025-09-30 05:00:27.416789 | 
2025-09-30 05:00:27.416866 | PLAY [all]
2025-09-30 05:00:27.424574 | 
2025-09-30 05:00:27.424641 | TASK [Gather network facts]
2025-09-30 05:00:27.931437 | controller | ok
2025-09-30 05:00:27.953107 | 
2025-09-30 05:00:27.953220 | TASK [include_role : start-zuul-console]
2025-09-30 05:00:27.971815 | controller | ok
2025-09-30 05:00:27.985210 | 
2025-09-30 05:00:27.985343 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-30 05:00:28.436058 | controller | ok
2025-09-30 05:00:28.451800 | 
2025-09-30 05:00:28.451902 | TASK [include_role : add-build-sshkey]
2025-09-30 05:00:28.494717 | controller | ok
2025-09-30 05:00:28.537650 | 
2025-09-30 05:00:28.537795 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-30 05:00:28.785331 | controller -> localhost | ok
2025-09-30 05:00:28.794675 | 
2025-09-30 05:00:28.794920 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-30 05:00:28.829842 | controller | ok
2025-09-30 05:00:28.845114 | controller | included: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-30 05:00:28.850634 | 
2025-09-30 05:00:28.850693 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-30 05:00:29.505603 | controller -> localhost | Generating public/private rsa key pair.
2025-09-30 05:00:29.505855 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/work/799f6515b14e4a6fbd7fa21fb344a34d_id_rsa.
2025-09-30 05:00:29.505892 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/work/799f6515b14e4a6fbd7fa21fb344a34d_id_rsa.pub.
2025-09-30 05:00:29.505916 | controller -> localhost | The key fingerprint is:
2025-09-30 05:00:29.505937 | controller -> localhost | SHA256:01bcWVg4ACsEJnypbLB6hLk2InVXRBs9X5PDW2f5I+s zuul-build-sshkey
2025-09-30 05:00:29.505957 | controller -> localhost | The key's randomart image is:
2025-09-30 05:00:29.505976 | controller -> localhost | +---[RSA 3072]----+
2025-09-30 05:00:29.505995 | controller -> localhost | |   .. o==....o =+|
2025-09-30 05:00:29.506015 | controller -> localhost | |  . .oo..ooo .X++|
2025-09-30 05:00:29.506034 | controller -> localhost | | o + o .o .oo.oBo|
2025-09-30 05:00:29.506053 | controller -> localhost | |o + = .  o ......|
2025-09-30 05:00:29.506072 | controller -> localhost | | = o .  S o   o .|
2025-09-30 05:00:29.506091 | controller -> localhost | |=o.      o   .   |
2025-09-30 05:00:29.506109 | controller -> localhost | |+..         .    |
2025-09-30 05:00:29.506128 | controller -> localhost | |             E   |
2025-09-30 05:00:29.506146 | controller -> localhost | |                 |
2025-09-30 05:00:29.506164 | controller -> localhost | +----[SHA256]-----+
2025-09-30 05:00:29.506208 | controller -> localhost | ok: Runtime: 0:00:00.231304
2025-09-30 05:00:29.514632 | 
2025-09-30 05:00:29.514775 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-30 05:00:29.549775 | controller | ok
2025-09-30 05:00:29.570100 | controller | included: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-30 05:00:29.584488 | 
2025-09-30 05:00:29.584635 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-30 05:00:29.610423 | controller | skipping: Conditional result was False
2025-09-30 05:00:29.616485 | 
2025-09-30 05:00:29.616570 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-30 05:00:30.083756 | controller | changed
2025-09-30 05:00:30.091112 | 
2025-09-30 05:00:30.091195 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-30 05:00:30.379020 | controller | ok
2025-09-30 05:00:30.386039 | 
2025-09-30 05:00:30.386156 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-30 05:00:31.347647 | controller | changed
2025-09-30 05:00:31.353646 | 
2025-09-30 05:00:31.353816 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-30 05:00:32.268104 | controller | changed
2025-09-30 05:00:32.273276 | 
2025-09-30 05:00:32.273354 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-30 05:00:32.297785 | controller | skipping: Conditional result was False
2025-09-30 05:00:32.304921 | 
2025-09-30 05:00:32.304998 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-30 05:00:32.646313 | controller -> localhost | changed
2025-09-30 05:00:32.656457 | 
2025-09-30 05:00:32.656562 | TASK [add-build-sshkey : Add back temp key]
2025-09-30 05:00:32.990534 | controller -> localhost | Identity added: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/work/799f6515b14e4a6fbd7fa21fb344a34d_id_rsa (zuul-build-sshkey)
2025-09-30 05:00:32.990788 | controller -> localhost | ok: Runtime: 0:00:00.011795
2025-09-30 05:00:32.996558 | 
2025-09-30 05:00:32.996629 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-30 05:00:33.402766 | controller | ok
2025-09-30 05:00:33.408584 | 
2025-09-30 05:00:33.408664 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-30 05:00:33.448506 | controller | skipping: Conditional result was False
2025-09-30 05:00:33.485524 | 
2025-09-30 05:00:33.485710 | TASK [include_role : validate-host]
2025-09-30 05:00:33.540558 | controller | ok
2025-09-30 05:00:33.576326 | 
2025-09-30 05:00:33.576865 | TASK [validate-host : Define zuul_info_dir fact]
2025-09-30 05:00:33.606411 | controller | ok
2025-09-30 05:00:33.614077 | 
2025-09-30 05:00:33.614191 | TASK [validate-host : Ensure Zuul Ansible directory exists]
2025-09-30 05:00:33.925068 | controller -> localhost | ok
2025-09-30 05:00:33.931435 | 
2025-09-30 05:00:33.931555 | TASK [validate-host : Collect information about the host]
2025-09-30 05:00:34.775700 | controller | ok
2025-09-30 05:00:34.787287 | 
2025-09-30 05:00:34.787372 | TASK [validate-host : Sanitize hostname]
2025-09-30 05:00:34.836784 | controller | ok
2025-09-30 05:00:34.842247 | 
2025-09-30 05:00:34.842352 | TASK [validate-host : Write out all ansible variables/facts known for each host]
2025-09-30 05:00:35.418936 | controller -> localhost | changed
2025-09-30 05:00:35.424166 | 
2025-09-30 05:00:35.424228 | TASK [validate-host : Collect information about zuul worker]
2025-09-30 05:00:35.869913 | controller | ok
2025-09-30 05:00:35.876627 | 
2025-09-30 05:00:35.876692 | TASK [validate-host : Write out all zuul information for each host]
2025-09-30 05:00:36.504617 | controller -> localhost | changed
2025-09-30 05:00:36.515508 | 
2025-09-30 05:00:36.515608 | TASK [include_role : prepare-workspace-openshift]
2025-09-30 05:00:36.556326 | controller | skipping: Conditional result was False
2025-09-30 05:00:36.563289 | 
2025-09-30 05:00:36.563362 | TASK [include_role : remove-zuul-sshkey]
2025-09-30 05:00:36.604834 | controller | skipping: Conditional result was False
2025-09-30 05:00:36.611099 | 
2025-09-30 05:00:36.611203 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 05:00:36.913120 | controller | ok: "logs"
2025-09-30 05:00:36.913359 | controller | ok: All items complete
2025-09-30 05:00:36.913394 | 
2025-09-30 05:00:37.184190 | controller | ok: "artifacts"
2025-09-30 05:00:37.402991 | controller | ok: "docs"
2025-09-30 05:00:37.412921 | 
2025-09-30 05:00:37.413037 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 05:00:37.697179 | controller | changed: "logs"
2025-09-30 05:00:37.954688 | controller | changed: "artifacts"
2025-09-30 05:00:38.147357 | controller | changed: "docs"
2025-09-30 05:00:38.185693 | 
2025-09-30 05:00:38.185946 | PLAY RECAP
2025-09-30 05:00:38.186125 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0
2025-09-30 05:00:38.186157 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 05:00:38.186177 | 
2025-09-30 05:00:38.304858 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master]
2025-09-30 05:00:38.305676 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-09-30 05:00:38.943047 | 
2025-09-30 05:00:38.943152 | PLAY [localhost]
2025-09-30 05:00:38.965978 | 
2025-09-30 05:00:38.966105 | TASK [configure-ssh-config-fips : Ensure ssh config directory]
2025-09-30 05:00:39.492288 | localhost | ok
2025-09-30 05:00:39.510875 | 
2025-09-30 05:00:39.511007 | TASK [configure-ssh-config-fips : Setup ssh config]
2025-09-30 05:00:40.351837 | localhost | changed
2025-09-30 05:00:40.374672 | 
2025-09-30 05:00:40.374788 | PLAY [all]
2025-09-30 05:00:40.393817 | 
2025-09-30 05:00:40.393937 | TASK [include_role : prepare-workspace]
2025-09-30 05:00:40.423549 | controller | ok
2025-09-30 05:00:40.439415 | 
2025-09-30 05:00:40.439547 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-30 05:00:40.819973 | controller | ok
2025-09-30 05:00:40.837420 | 
2025-09-30 05:00:40.837549 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-30 05:00:42.573890 | controller | Output suppressed because no_log was given
2025-09-30 05:00:42.601936 | 
2025-09-30 05:00:42.602042 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-30 05:00:42.900702 | controller | changed: "logs"
2025-09-30 05:00:43.117158 | controller | changed: "artifacts"
2025-09-30 05:00:43.310942 | controller | changed: "docs"
2025-09-30 05:00:43.320369 | 
2025-09-30 05:00:43.320476 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-30 05:00:43.567656 | controller | changed: "logs"
2025-09-30 05:00:43.567903 | controller | changed: All items complete
2025-09-30 05:00:43.567931 | 
2025-09-30 05:00:43.764680 | controller | changed: "artifacts"
2025-09-30 05:00:43.953568 | controller | changed: "docs"
2025-09-30 05:00:43.985004 | 
2025-09-30 05:00:43.985100 | TASK [Check if worker can sudo]
2025-09-30 05:00:45.033583 | controller | ok: Runtime: 0:00:00.042924
2025-09-30 05:00:45.044462 | 
2025-09-30 05:00:45.044555 | TASK [configure-mirrors : Gather needed facts]
2025-09-30 05:00:45.147767 | controller | skipping: Conditional result was False
2025-09-30 05:00:45.154467 | 
2025-09-30 05:00:45.154563 | TASK [configure-mirrors : Set up infrastructure mirrors]
2025-09-30 05:00:45.256228 | controller | ok
2025-09-30 05:00:45.265142 | controller | included: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml
2025-09-30 05:00:45.297471 | 
2025-09-30 05:00:45.297603 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir]
2025-09-30 05:00:45.574139 | controller | ok
2025-09-30 05:00:45.581716 | 
2025-09-30 05:00:45.581805 | LOOP [configure-mirrors : Include OS-specific variables]
2025-09-30 05:00:45.653161 | controller | ok: "/var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml"
2025-09-30 05:00:45.668408 | 
2025-09-30 05:00:45.668519 | TASK [configure-mirrors : Install /etc/pip.conf configuration]
2025-09-30 05:00:46.638184 | controller | changed
2025-09-30 05:00:46.643788 | 
2025-09-30 05:00:46.643861 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors]
2025-09-30 05:00:46.723817 | controller | ok: "/var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml"
2025-09-30 05:00:46.723975 | controller | ok: All items complete
2025-09-30 05:00:46.724004 | 
2025-09-30 05:00:46.813834 | controller | included: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml
2025-09-30 05:00:46.820827 | 
2025-09-30 05:00:46.820917 | LOOP [configure-mirrors : Install CentOS 9 repository files]
2025-09-30 05:00:47.855220 | controller | changed: "etc/yum.repos.d/centos.repo"
2025-09-30 05:00:48.693445 | controller | changed: "etc/yum.repos.d/centos-addons.repo"
2025-09-30 05:00:48.701773 | 
2025-09-30 05:00:48.701841 | TASK [configure-mirrors : Disable deltrarpm]
2025-09-30 05:00:49.151781 | controller | changed: section and option added
2025-09-30 05:00:49.172647 | 
2025-09-30 05:00:49.172782 | LOOP [configure-mirrors : Update yum/dnf cache]
2025-09-30 05:00:49.968495 | controller | 29 files removed
2025-09-30 05:00:49.970830 | controller | ok: Item: dnf clean all Runtime: 0:00:00.448477
2025-09-30 05:00:49.970917 | controller | changed: All items complete
2025-09-30 05:00:49.970953 | 
2025-09-30 05:01:00.234291 | 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-09-30 05:01:00.234405 | controller | DNF version: 4.14.0
2025-09-30 05:01:00.234441 | controller | cachedir: /var/cache/dnf
2025-09-30 05:01:00.234468 | controller | Making cache files for all metadata files.
2025-09-30 05:01:00.234488 | controller | baseos: has expired and will be refreshed.
2025-09-30 05:01:00.234509 | controller | appstream: has expired and will be refreshed.
2025-09-30 05:01:00.234533 | controller | crb: has expired and will be refreshed.
2025-09-30 05:01:00.234564 | controller | extras-common: has expired and will be refreshed.
2025-09-30 05:01:00.234582 | controller | repo: downloading from remote: baseos
2025-09-30 05:01:00.234604 | controller | CentOS Stream 9 - BaseOS                         75 MB/s | 8.8 MB     00:00
2025-09-30 05:01:00.234627 | controller | baseos: using metadata from Mon 22 Sep 2025 10:29:43 AM EDT.
2025-09-30 05:01:00.234652 | controller | repo: downloading from remote: appstream
2025-09-30 05:01:00.234670 | controller | CentOS Stream 9 - AppStream                     103 MB/s |  25 MB     00:00
2025-09-30 05:01:00.234688 | controller | appstream: using metadata from Mon 22 Sep 2025 10:33:24 AM EDT.
2025-09-30 05:01:00.234711 | controller | repo: downloading from remote: crb
2025-09-30 05:01:00.234752 | controller | CentOS Stream 9 - CRB                            91 MB/s | 7.1 MB     00:00
2025-09-30 05:01:00.234771 | controller | crb: using metadata from Mon 22 Sep 2025 10:37:51 AM EDT.
2025-09-30 05:01:00.234786 | controller | repo: downloading from remote: extras-common
2025-09-30 05:01:00.234802 | controller | CentOS Stream 9 - Extras packages               1.6 MB/s |  20 kB     00:00
2025-09-30 05:01:00.234818 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT.
2025-09-30 05:01:00.234834 | controller | Last metadata expiration check: 0:00:01 ago on Tue 30 Sep 2025 01:00:58 AM EDT.
2025-09-30 05:01:00.234850 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)'
2025-09-30 05:01:00.234866 | controller | Completion plugin: Generating completion cache...
2025-09-30 05:01:00.234882 | controller | Metadata cache created.
2025-09-30 05:01:00.234907 | controller | ok: Item: dnf makecache -v Runtime: 0:00:09.968768
2025-09-30 05:01:00.256829 | 
2025-09-30 05:01:00.256914 | PLAY RECAP
2025-09-30 05:01:00.256955 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0
2025-09-30 05:01:00.256979 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-30 05:01:00.256997 | 
2025-09-30 05:01:00.508331 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master]
2025-09-30 05:01:00.509176 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 05:01:01.669985 | 
2025-09-30 05:01:01.670136 | PLAY [all]
2025-09-30 05:01:01.698059 | 
2025-09-30 05:01:01.698186 | TASK [Install binary dependencies]
2025-09-30 05:01:01.820113 | controller | ok
2025-09-30 05:01:01.874472 | 
2025-09-30 05:01:01.874628 | TASK [bindep : Include find tasks]
2025-09-30 05:01:01.920047 | controller | ok
2025-09-30 05:01:01.934272 | controller | included: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-30 05:01:01.950839 | 
2025-09-30 05:01:01.950962 | TASK [bindep : Look for bindep.txt]
2025-09-30 05:01:02.410870 | controller | ok
2025-09-30 05:01:02.423458 | 
2025-09-30 05:01:02.423565 | TASK [bindep : Define bindep_file fact]
2025-09-30 05:01:02.474206 | controller | ok
2025-09-30 05:01:02.485020 | 
2025-09-30 05:01:02.485127 | TASK [bindep : Look for other-requirements.txt]
2025-09-30 05:01:02.499704 | controller | skipping: Conditional result was False
2025-09-30 05:01:02.506239 | 
2025-09-30 05:01:02.506319 | TASK [bindep : Define bindep_file fact]
2025-09-30 05:01:02.532622 | controller | skipping: Conditional result was False
2025-09-30 05:01:02.538382 | 
2025-09-30 05:01:02.538451 | TASK [bindep : Look for bindep fallback file]
2025-09-30 05:01:02.562801 | controller | skipping: Conditional result was False
2025-09-30 05:01:02.568376 | 
2025-09-30 05:01:02.568444 | TASK [bindep : Define bindep_file fact]
2025-09-30 05:01:02.592046 | controller | skipping: Conditional result was False
2025-09-30 05:01:02.597635 | 
2025-09-30 05:01:02.597698 | TASK [bindep : Include bindep tasks]
2025-09-30 05:01:02.634205 | controller | ok
2025-09-30 05:01:02.642709 | controller | included: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml
2025-09-30 05:01:02.650208 | 
2025-09-30 05:01:02.650274 | TASK [bindep : Look for bindep command]
2025-09-30 05:01:02.674002 | controller | skipping: Conditional result was False
2025-09-30 05:01:02.680265 | 
2025-09-30 05:01:02.680331 | TASK [bindep : Check for system bindep]
2025-09-30 05:01:03.229774 | controller | ok: Runtime: 0:00:00.007088
2025-09-30 05:01:03.240206 | 
2025-09-30 05:01:03.240313 | TASK [bindep : Define bindep_command fact]
2025-09-30 05:01:03.284937 | controller | skipping: Conditional result was False
2025-09-30 05:01:03.290656 | 
2025-09-30 05:01:03.290719 | TASK [bindep : Include install tasks]
2025-09-30 05:01:03.329565 | controller | ok
2025-09-30 05:01:03.336702 | controller | included: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml
2025-09-30 05:01:03.345368 | 
2025-09-30 05:01:03.345430 | TASK [bindep : Create temp dir for bindep]
2025-09-30 05:01:03.753200 | controller | changed
2025-09-30 05:01:03.760397 | 
2025-09-30 05:01:03.760480 | TASK [Ensure we have pip dependencies]
2025-09-30 05:01:03.782422 | controller | ok
2025-09-30 05:01:03.826427 | 
2025-09-30 05:01:03.826546 | TASK [ensure-pip : Check if pip is installed]
2025-09-30 01:01:04.084569 | controller | /usr/bin/pip3
2025-09-30 01:01:04.104155 | controller | /usr/bin/python3: No module named wheel
2025-09-30 05:01:04.353109 | controller | ok: Runtime: 0:00:00.030114
2025-09-30 05:01:04.363041 | 
2025-09-30 05:01:04.363194 | LOOP [ensure-pip : Install pip from packages]
2025-09-30 05:01:04.416025 | controller | ok: "/var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml"
2025-09-30 05:01:04.432577 | controller | included: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml
2025-09-30 05:01:04.452629 | 
2025-09-30 05:01:04.452755 | TASK [ensure-pip : Install Python 3 pip]
2025-09-30 05:01:06.792304 | controller | changed
2025-09-30 05:01:06.797645 | 
2025-09-30 05:01:06.797707 | TASK [ensure-pip : Check for EPEL repository]
2025-09-30 05:01:06.848680 | controller | skipping: Conditional result was False
2025-09-30 05:01:06.854567 | 
2025-09-30 05:01:06.854636 | TASK [ensure-pip : Fail with instructions when EPEL is not installed]
2025-09-30 05:01:06.920983 | controller | skipping: Conditional result was False
2025-09-30 05:01:06.927951 | 
2025-09-30 05:01:06.928052 | TASK [ensure-pip : Install Python 2 pip]
2025-09-30 05:01:06.972155 | controller | skipping: Conditional result was False
2025-09-30 05:01:06.978772 | 
2025-09-30 05:01:06.978845 | TASK [ensure-pip : Ensure setuptools]
2025-09-30 05:01:07.028774 | controller | skipping: Conditional result was False
2025-09-30 05:01:07.035072 | 
2025-09-30 05:01:07.035141 | TASK [ensure-pip : Check for ensurepip module]
2025-09-30 05:01:07.573931 | controller | skipping: Conditional result was False
2025-09-30 05:01:07.583893 | 
2025-09-30 05:01:07.584055 | TASK [ensure-pip : Ensure python3-venv]
2025-09-30 05:01:07.610590 | controller | skipping: Conditional result was False
2025-09-30 05:01:07.619545 | 
2025-09-30 05:01:07.619643 | TASK [ensure-pip : Install pip from source]
2025-09-30 05:01:07.633426 | controller | skipping: Conditional result was False
2025-09-30 05:01:07.639626 | 
2025-09-30 05:01:07.639712 | TASK [ensure-pip : Probe for venv python full path]
2025-09-30 01:01:07.925704 | controller | /usr/bin/python3
2025-09-30 05:01:08.175301 | controller | ok: Runtime: 0:00:00.007120
2025-09-30 05:01:08.185369 | 
2025-09-30 05:01:08.185531 | TASK [ensure-pip : Set host default]
2025-09-30 05:01:08.255097 | controller | ok
2025-09-30 05:01:08.262385 | 
2025-09-30 05:01:08.262474 | TASK [ensure-pip : Set ensure_pip_virtualenv_command]
2025-09-30 05:01:08.316360 | controller | ok
2025-09-30 05:01:08.326208 | 
2025-09-30 05:01:08.326269 | TASK [bindep : Install bindep into temporary venv]
2025-09-30 05:01:12.654312 | controller | changed
2025-09-30 05:01:12.662329 | 
2025-09-30 05:01:12.662447 | TASK [bindep : Define bindep_command]
2025-09-30 05:01:12.705371 | controller | ok
2025-09-30 05:01:12.717812 | 
2025-09-30 05:01:12.717977 | LOOP [bindep : Include package tasks]
2025-09-30 05:01:12.781652 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt"
2025-09-30 05:01:12.781903 | controller | ok: All items complete
2025-09-30 05:01:12.781934 | 
2025-09-30 05:01:12.804833 | controller | included: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml
2025-09-30 05:01:12.825214 | 
2025-09-30 05:01:12.825377 | TASK [bindep : Define bindep_run fact]
2025-09-30 05:01:12.856954 | controller | ok
2025-09-30 05:01:12.864122 | 
2025-09-30 05:01:12.864196 | TASK [bindep : Get list of packages to install from bindep]
2025-09-30 01:01:14.562759 | controller | podman
2025-09-30 01:01:14.614667 | controller | python3-jmespath
2025-09-30 01:01:14.614876 | controller | python3-libvirt
2025-09-30 01:01:14.614898 | controller | python3-lxml
2025-09-30 01:01:14.614918 | controller | python3-netaddr
2025-09-30 05:01:14.921094 | controller | ok: Runtime: 0:00:01.447131
2025-09-30 05:01:14.928679 | 
2025-09-30 05:01:14.928799 | TASK [bindep : Install distro packages from bindep]
2025-09-30 05:02:15.263286 | controller | changed
2025-09-30 05:02:15.275683 | 
2025-09-30 05:02:15.275882 | TASK [bindep : Check that packages are installed]
2025-09-30 05:02:17.325955 | controller | ok: Runtime: 0:00:01.501834
2025-09-30 05:02:17.340956 | 
2025-09-30 05:02:17.341175 | TASK [bindep : Fail if we cannot install all packages]
2025-09-30 05:02:17.379923 | controller | skipping: Conditional result was False
2025-09-30 05:02:17.405535 | 
2025-09-30 05:02:17.405765 | TASK [Run test-setup role]
2025-09-30 05:02:17.434652 | controller | ok
2025-09-30 05:02:17.466093 | 
2025-09-30 05:02:17.466275 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-30 05:02:17.724559 | controller | ok
2025-09-30 05:02:17.732461 | 
2025-09-30 05:02:17.732561 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-30 05:02:18.280386 | controller | skipping: Conditional result was False
2025-09-30 05:02:18.327052 | 
2025-09-30 05:02:18.327253 | TASK [bindep : Remove bindep temp dir]
2025-09-30 05:02:18.776819 | controller | ok
2025-09-30 05:02:18.800981 | 
2025-09-30 05:02:18.801118 | PLAY RECAP
2025-09-30 05:02:18.801207 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0
2025-09-30 05:02:18.801252 | 
2025-09-30 05:02:18.941920 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-30 05:02:18.943648 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-09-30 05:02:19.588224 | 
2025-09-30 05:02:19.588332 | PLAY [all]
2025-09-30 05:02:19.607336 | 
2025-09-30 05:02:19.607419 | TASK [Abort when test_command variable is undefined]
2025-09-30 05:02:19.631960 | controller | skipping: Conditional result was False
2025-09-30 05:02:19.637879 | 
2025-09-30 05:02:19.637954 | TASK [Convert test_command to list]
2025-09-30 05:02:19.692622 | controller | skipping: Conditional result was False
2025-09-30 05:02:19.698936 | 
2025-09-30 05:02:19.699004 | TASK [Use test_command list]
2025-09-30 05:02:19.758652 | controller | ok
2025-09-30 05:02:19.764058 | 
2025-09-30 05:02:19.764128 | LOOP [Run test_command]
2025-09-30 05:02:20.194557 | controller | no check to run
2025-09-30 05:02:20.194781 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.008452
2025-09-30 05:02:20.215759 | 
2025-09-30 05:02:20.215864 | PLAY RECAP
2025-09-30 05:02:20.215903 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-30 05:02:20.216009 | 
2025-09-30 05:02:20.312505 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master]
2025-09-30 05:02:20.313662 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 05:02:20.956168 | 
2025-09-30 05:02:20.956286 | PLAY [all]
2025-09-30 05:02:20.977357 | 
2025-09-30 05:02:20.977511 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-30 05:02:21.495208 | controller | changed: non-zero return code
2025-09-30 05:02:21.509111 | 
2025-09-30 05:02:21.509336 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-30 05:02:21.529034 | controller | skipping: Conditional result was False
2025-09-30 05:02:21.543522 | 
2025-09-30 05:02:21.543687 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-30 05:02:21.576460 | 
2025-09-30 05:02:21.576789 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-30 05:02:21.610401 | 
2025-09-30 05:02:21.610707 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-30 05:02:21.629015 | controller | skipping: Conditional result was False
2025-09-30 05:02:21.638504 | 
2025-09-30 05:02:21.638606 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-30 05:02:21.663970 | 
2025-09-30 05:02:21.664166 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-30 05:02:21.679350 | controller | skipping: Conditional result was False
2025-09-30 05:02:21.688350 | 
2025-09-30 05:02:21.688469 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-30 05:02:21.703830 | controller | skipping: Conditional result was False
2025-09-30 05:02:21.712698 | 
2025-09-30 05:02:21.712816 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-30 05:02:21.728455 | controller | skipping: Conditional result was False
2025-09-30 05:02:21.763415 | 
2025-09-30 05:02:21.763515 | PLAY RECAP
2025-09-30 05:02:21.763558 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-30 05:02:21.763578 | 
2025-09-30 05:02:21.856497 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-30 05:02:21.858439 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 05:02:22.482391 | 
2025-09-30 05:02:22.482512 | PLAY [all]
2025-09-30 05:02:22.503093 | 
2025-09-30 05:02:22.503220 | TASK [include_role : fetch-output]
2025-09-30 05:02:22.544030 | controller | ok
2025-09-30 05:02:22.562409 | 
2025-09-30 05:02:22.562524 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-30 05:02:22.638227 | controller | skipping: Conditional result was False
2025-09-30 05:02:22.644376 | 
2025-09-30 05:02:22.644454 | TASK [fetch-output : Set log path for single node]
2025-09-30 05:02:22.703139 | controller | ok
2025-09-30 05:02:22.718908 | 
2025-09-30 05:02:22.719111 | LOOP [fetch-output : Ensure local output dirs]
2025-09-30 05:02:23.192255 | controller -> localhost | ok: "/var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/work/logs"
2025-09-30 05:02:23.490184 | controller -> localhost | changed: "/var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/work/artifacts"
2025-09-30 05:02:23.780292 | controller -> localhost | changed: "/var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/work/docs"
2025-09-30 05:02:23.810366 | 
2025-09-30 05:02:23.810592 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-30 05:02:24.587195 | controller | changed: .d..t...... ./
2025-09-30 05:02:24.587599 | controller | changed: All items complete
2025-09-30 05:02:24.587667 | 
2025-09-30 05:02:25.179300 | controller | changed: .d..t...... ./
2025-09-30 05:02:25.786789 | controller | changed: .d..t...... ./
2025-09-30 05:02:25.817266 | 
2025-09-30 05:02:25.817476 | TASK [include_role : fetch-output-openshift]
2025-09-30 05:02:25.845271 | controller | skipping: Conditional result was False
2025-09-30 05:02:25.860523 | 
2025-09-30 05:02:25.860709 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-30 05:02:26.369847 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.010448
2025-09-30 05:02:26.594012 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.011181
2025-09-30 05:02:26.638056 | 
2025-09-30 05:02:26.638255 | PLAY [all]
2025-09-30 05:02:26.660394 | 
2025-09-30 05:02:26.660532 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes]
2025-09-30 05:02:27.107626 | controller | changed
2025-09-30 05:02:27.131937 | 
2025-09-30 05:02:27.132067 | PLAY RECAP
2025-09-30 05:02:27.132113 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0
2025-09-30 05:02:27.132134 | 
2025-09-30 05:02:27.228187 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master]
2025-09-30 05:02:27.229072 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master]
2025-09-30 05:02:27.884057 | 
2025-09-30 05:02:27.884168 | PLAY [localhost]
2025-09-30 05:02:27.902987 | 
2025-09-30 05:02:27.903102 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-30 05:02:28.323389 | localhost | changed
2025-09-30 05:02:28.333336 | 
2025-09-30 05:02:28.333510 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-30 05:02:28.370200 | localhost | ok
2025-09-30 05:02:28.388658 | 
2025-09-30 05:02:28.388893 | TASK [add-fileserver : Create SSH private key tempfile]
2025-09-30 05:02:28.849034 | localhost | changed
2025-09-30 05:02:28.856596 | 
2025-09-30 05:02:28.856711 | TASK [add-fileserver : Create SSH private key from secret]
2025-09-30 05:02:29.580843 | localhost | changed
2025-09-30 05:02:29.586341 | 
2025-09-30 05:02:29.586404 | TASK [add-fileserver : Add fileserver ssh key]
2025-09-30 05:02:29.972683 | localhost | Identity added: /var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/work/tmp/ansible.l8l82ygo (/var/lib/zuul/builds/799f6515b14e4a6fbd7fa21fb344a34d/work/tmp/ansible.l8l82ygo)
2025-09-30 05:02:29.972915 | localhost | ok: Runtime: 0:00:00.013130
2025-09-30 05:02:29.977232 | 
2025-09-30 05:02:29.977294 | TASK [add-fileserver : Remove SSH private key from disk]
2025-09-30 05:02:30.291544 | localhost | ok: Runtime: 0:00:00.023097
2025-09-30 05:02:30.296522 | 
2025-09-30 05:02:30.296595 | TASK [add-fileserver : Add fileserver to inventory]
2025-09-30 05:02:30.373387 | localhost | changed
2025-09-30 05:02:30.382857 | 
2025-09-30 05:02:30.382991 | TASK [add-fileserver : Add fileserver server to known hosts]
2025-09-30 05:02:30.862160 | localhost | changed
2025-09-30 05:02:30.882984 | 
2025-09-30 05:02:30.883137 | PLAY [localhost]
2025-09-30 05:02:30.895934 | 
2025-09-30 05:02:30.896030 | TASK [Generate bulk log download script]
2025-09-30 05:02:30.916636 | localhost | ok
2025-09-30 05:02:30.928634 | 
2025-09-30 05:02:30.928774 | TASK [local-log-download : Check API endpoint is defined]
2025-09-30 05:02:30.978309 | localhost | ok: All assertions passed
2025-09-30 05:02:30.983176 | 
2025-09-30 05:02:30.983242 | TASK [local-log-download : Create download script]
2025-09-30 05:02:31.458452 | localhost -> localhost | changed
2025-09-30 05:02:31.469156 | 
2025-09-30 05:02:31.469227 | TASK [Register quick-download link]
2025-09-30 05:02:31.488402 | localhost | ok
2025-09-30 05:02:31.532979 | 
2025-09-30 05:02:31.533072 | PLAY [logserver.rdoproject.org]
2025-09-30 05:02:31.556302 | 
2025-09-30 05:02:31.556507 | TASK [Set zuul-log-path fact]
2025-09-30 05:02:31.580619 | logserver.rdoproject.org | ok
2025-09-30 05:02:31.603559 | 
2025-09-30 05:02:31.603783 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-30 05:02:31.647966 | logserver.rdoproject.org | ok
2025-09-30 05:02:31.660872 | 
2025-09-30 05:02:31.661044 | TASK [upload-logs : Create log directories]
2025-09-30 05:02:32.368501 | logserver.rdoproject.org | changed
2025-09-30 05:02:32.376026 | 
2025-09-30 05:02:32.376184 | TASK [upload-logs : Ensure logs are readable before uploading]
2025-09-30 05:02:32.730163 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.008711
2025-09-30 05:02:32.735281 | 
2025-09-30 05:02:32.735344 | TASK [upload-logs : Upload logs to log server]
2025-09-30 05:02:33.459349 | logserver.rdoproject.org | Output suppressed because no_log was given
2025-09-30 05:02:33.462629 | 
2025-09-30 05:02:33.462716 | LOOP [upload-logs : Compress console log and json output]
2025-09-30 05:02:33.508342 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 05:02:33.517648 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 05:02:33.522317 | 
2025-09-30 05:02:33.522429 | LOOP [upload-logs : Upload compressed console log and json output]
2025-09-30 05:02:33.566380 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 05:02:33.566620 | 
2025-09-30 05:02:33.569861 | logserver.rdoproject.org | skipping: Conditional result was False
2025-09-30 05:02:33.576653 | 
2025-09-30 05:02:33.577168 | LOOP [upload-logs : Upload console log and json output]