2025-09-30 06:39:37.729473 | Job console starting... 2025-09-30 06:39:37.745894 | Updating repositories 2025-09-30 06:39:37.778963 | Preparing job workspace 2025-09-30 06:39:41.821635 | Running Ansible setup... 2025-09-30 06:39:45.783456 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-30 06:39:46.417781 | 2025-09-30 06:39:46.417885 | PLAY [localhost] 2025-09-30 06:39:46.436416 | 2025-09-30 06:39:46.436485 | TASK [Gathering Facts] 2025-09-30 06:39:47.322301 | localhost | ok 2025-09-30 06:39:47.355733 | 2025-09-30 06:39:47.355964 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-30 06:39:47.747530 | localhost -> localhost | changed 2025-09-30 06:39:47.759715 | 2025-09-30 06:39:47.759874 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-30 06:39:48.612198 | localhost -> localhost | changed 2025-09-30 06:39:48.622494 | 2025-09-30 06:39:48.622568 | TASK [Setup log path fact] 2025-09-30 06:39:48.642999 | localhost | ok 2025-09-30 06:39:48.657941 | 2025-09-30 06:39:48.658027 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-30 06:39:48.685157 | localhost | ok 2025-09-30 06:39:48.692794 | 2025-09-30 06:39:48.692856 | TASK [emit-job-header : Print job information] 2025-09-30 06:39:48.730063 | # Job Information 2025-09-30 06:39:48.730205 | Ansible Version: 2.15.12 2025-09-30 06:39:48.730230 | Job: cifmw-molecule-cifmw_helpers 2025-09-30 06:39:48.730250 | Pipeline: github-check 2025-09-30 06:39:48.730269 | Executor: ze04.softwarefactory-project.io 2025-09-30 06:39:48.730286 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333 2025-09-30 06:39:48.730305 | Log URL (when completed): https://logserver.rdoproject.org/c2a/rdoproject.org/c2a60d22e8fb480baa7198881ced9df7/ 2025-09-30 06:39:48.730323 | Event ID: 04e0d970-9dc8-11f0-9216-1f816847bc0d 2025-09-30 06:39:48.733906 | 2025-09-30 06:39:48.733966 | LOOP [emit-job-header : Print node information] 2025-09-30 06:39:48.854808 | localhost | ok: 2025-09-30 06:39:48.855105 | localhost | # Node Information 2025-09-30 06:39:48.855140 | localhost | Inventory Hostname: controller 2025-09-30 06:39:48.855169 | localhost | Hostname: np0005461798 2025-09-30 06:39:48.855189 | localhost | Username: zuul 2025-09-30 06:39:48.855209 | localhost | Distro: CentOS 9 2025-09-30 06:39:48.855227 | localhost | Provider: vexxhost-nodepool-tripleo 2025-09-30 06:39:48.855244 | localhost | Region: RegionOne 2025-09-30 06:39:48.855261 | localhost | Label: cloud-centos-9-stream-tripleo 2025-09-30 06:39:48.855278 | localhost | Product Name: OpenStack Nova 2025-09-30 06:39:48.855295 | localhost | Interface IP: 38.102.83.110 2025-09-30 06:39:48.897557 | 2025-09-30 06:39:48.897647 | PLAY [all] 2025-09-30 06:39:48.904347 | 2025-09-30 06:39:48.904409 | TASK [Gather network facts] 2025-09-30 06:39:49.434553 | controller | ok 2025-09-30 06:39:49.476440 | 2025-09-30 06:39:49.476540 | TASK [include_role : start-zuul-console] 2025-09-30 06:39:49.506796 | controller | ok 2025-09-30 06:39:49.519363 | 2025-09-30 06:39:49.519434 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-30 06:39:49.946587 | controller | ok 2025-09-30 06:39:49.956002 | 2025-09-30 06:39:49.956063 | TASK [include_role : add-build-sshkey] 2025-09-30 06:39:49.975013 | controller | ok 2025-09-30 06:39:49.987763 | 2025-09-30 06:39:49.987827 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-30 06:39:50.262114 | controller -> localhost | ok 2025-09-30 06:39:50.267865 | 2025-09-30 06:39:50.267925 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-30 06:39:50.298496 | controller | ok 2025-09-30 06:39:50.330455 | controller | included: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-30 06:39:50.343848 | 2025-09-30 06:39:50.343912 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-30 06:39:51.161807 | controller -> localhost | Generating public/private rsa key pair. 2025-09-30 06:39:51.162015 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/work/c2a60d22e8fb480baa7198881ced9df7_id_rsa. 2025-09-30 06:39:51.162046 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/work/c2a60d22e8fb480baa7198881ced9df7_id_rsa.pub. 2025-09-30 06:39:51.162067 | controller -> localhost | The key fingerprint is: 2025-09-30 06:39:51.162086 | controller -> localhost | SHA256:059KvKSoDV/Fq5ALq6Y7XOF0hBjYrBWJ94e2uXw/r10 zuul-build-sshkey 2025-09-30 06:39:51.162104 | controller -> localhost | The key's randomart image is: 2025-09-30 06:39:51.162122 | controller -> localhost | +---[RSA 3072]----+ 2025-09-30 06:39:51.162138 | controller -> localhost | |.=+o. | 2025-09-30 06:39:51.162157 | controller -> localhost | |o.*. . | 2025-09-30 06:39:51.162174 | controller -> localhost | | + ... | 2025-09-30 06:39:51.162192 | controller -> localhost | |. o+.. o | 2025-09-30 06:39:51.162210 | controller -> localhost | | o.o+ S + | 2025-09-30 06:39:51.162226 | controller -> localhost | | oo . + o . | 2025-09-30 06:39:51.162243 | controller -> localhost | |. ..o.o . = E | 2025-09-30 06:39:51.162262 | controller -> localhost | |... o*.=.* + | 2025-09-30 06:39:51.162280 | controller -> localhost | |o=..oo=.=+= | 2025-09-30 06:39:51.162297 | controller -> localhost | +----[SHA256]-----+ 2025-09-30 06:39:51.162341 | controller -> localhost | ok: Runtime: 0:00:00.305085 2025-09-30 06:39:51.170182 | 2025-09-30 06:39:51.170244 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-30 06:39:51.209209 | controller | ok 2025-09-30 06:39:51.219216 | controller | included: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-30 06:39:51.228749 | 2025-09-30 06:39:51.228823 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-30 06:39:51.252696 | controller | skipping: Conditional result was False 2025-09-30 06:39:51.258323 | 2025-09-30 06:39:51.258388 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-30 06:39:51.970472 | controller | changed 2025-09-30 06:39:51.977319 | 2025-09-30 06:39:51.977385 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-30 06:39:52.302857 | controller | ok 2025-09-30 06:39:52.310319 | 2025-09-30 06:39:52.310399 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-30 06:39:53.263653 | controller | changed 2025-09-30 06:39:53.268642 | 2025-09-30 06:39:53.268717 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-30 06:39:54.271034 | controller | changed 2025-09-30 06:39:54.283127 | 2025-09-30 06:39:54.283266 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-30 06:39:54.309920 | controller | skipping: Conditional result was False 2025-09-30 06:39:54.322627 | 2025-09-30 06:39:54.322822 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-30 06:39:54.726527 | controller -> localhost | changed 2025-09-30 06:39:54.736353 | 2025-09-30 06:39:54.736414 | TASK [add-build-sshkey : Add back temp key] 2025-09-30 06:39:54.978533 | controller -> localhost | Identity added: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/work/c2a60d22e8fb480baa7198881ced9df7_id_rsa (zuul-build-sshkey) 2025-09-30 06:39:54.978781 | controller -> localhost | ok: Runtime: 0:00:00.007944 2025-09-30 06:39:54.984537 | 2025-09-30 06:39:54.984594 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-30 06:39:55.378111 | controller | ok 2025-09-30 06:39:55.386080 | 2025-09-30 06:39:55.386165 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-30 06:39:55.430915 | controller | skipping: Conditional result was False 2025-09-30 06:39:55.442717 | 2025-09-30 06:39:55.442794 | TASK [include_role : validate-host] 2025-09-30 06:39:55.484103 | controller | ok 2025-09-30 06:39:55.528956 | 2025-09-30 06:39:55.529077 | TASK [validate-host : Define zuul_info_dir fact] 2025-09-30 06:39:55.587851 | controller | ok 2025-09-30 06:39:55.592535 | 2025-09-30 06:39:55.592594 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-09-30 06:39:55.819138 | controller -> localhost | ok 2025-09-30 06:39:55.824969 | 2025-09-30 06:39:55.825032 | TASK [validate-host : Collect information about the host] 2025-09-30 06:39:56.728405 | controller | ok 2025-09-30 06:39:56.743599 | 2025-09-30 06:39:56.743722 | TASK [validate-host : Sanitize hostname] 2025-09-30 06:39:56.801766 | controller | ok 2025-09-30 06:39:56.806583 | 2025-09-30 06:39:56.806642 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-09-30 06:39:57.268899 | controller -> localhost | changed 2025-09-30 06:39:57.274408 | 2025-09-30 06:39:57.274470 | TASK [validate-host : Collect information about zuul worker] 2025-09-30 06:39:57.743280 | controller | ok 2025-09-30 06:39:57.748216 | 2025-09-30 06:39:57.748277 | TASK [validate-host : Write out all zuul information for each host] 2025-09-30 06:39:58.329861 | controller -> localhost | changed 2025-09-30 06:39:58.357400 | 2025-09-30 06:39:58.357522 | TASK [include_role : prepare-workspace-openshift] 2025-09-30 06:39:58.512317 | controller | skipping: Conditional result was False 2025-09-30 06:39:58.517636 | 2025-09-30 06:39:58.517728 | TASK [include_role : remove-zuul-sshkey] 2025-09-30 06:39:58.592619 | controller | skipping: Conditional result was False 2025-09-30 06:39:58.598548 | 2025-09-30 06:39:58.598610 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-30 06:39:58.983703 | controller | ok: "logs" 2025-09-30 06:39:58.983962 | controller | ok: All items complete 2025-09-30 06:39:58.983989 | 2025-09-30 06:39:59.249977 | controller | ok: "artifacts" 2025-09-30 06:39:59.469586 | controller | ok: "docs" 2025-09-30 06:39:59.480828 | 2025-09-30 06:39:59.480948 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-30 06:39:59.828234 | controller | changed: "logs" 2025-09-30 06:40:00.059061 | controller | changed: "artifacts" 2025-09-30 06:40:00.268835 | controller | changed: "docs" 2025-09-30 06:40:00.317805 | 2025-09-30 06:40:00.317972 | PLAY RECAP 2025-09-30 06:40:00.318057 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-09-30 06:40:00.318114 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-30 06:40:00.318154 | 2025-09-30 06:40:00.456756 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-30 06:40:00.457669 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-09-30 06:40:01.021999 | 2025-09-30 06:40:01.022127 | PLAY [localhost] 2025-09-30 06:40:01.039602 | 2025-09-30 06:40:01.039750 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-09-30 06:40:01.454368 | localhost | ok 2025-09-30 06:40:01.464287 | 2025-09-30 06:40:01.464366 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-09-30 06:40:02.387069 | localhost | changed 2025-09-30 06:40:02.431158 | 2025-09-30 06:40:02.431213 | PLAY [all] 2025-09-30 06:40:02.452483 | 2025-09-30 06:40:02.452542 | TASK [include_role : prepare-workspace] 2025-09-30 06:40:02.499063 | controller | ok 2025-09-30 06:40:02.515847 | 2025-09-30 06:40:02.515955 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-30 06:40:02.956388 | controller | ok 2025-09-30 06:40:02.964181 | 2025-09-30 06:40:02.964246 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-30 06:40:04.862183 | controller | Output suppressed because no_log was given 2025-09-30 06:40:04.872117 | 2025-09-30 06:40:04.872183 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-30 06:40:05.148058 | controller | changed: "logs" 2025-09-30 06:40:05.379982 | controller | changed: "artifacts" 2025-09-30 06:40:05.632634 | controller | changed: "docs" 2025-09-30 06:40:05.640456 | 2025-09-30 06:40:05.640579 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-30 06:40:05.924390 | controller | changed: "logs" 2025-09-30 06:40:05.924628 | controller | changed: All items complete 2025-09-30 06:40:05.924661 | 2025-09-30 06:40:06.198152 | controller | changed: "artifacts" 2025-09-30 06:40:06.507559 | controller | changed: "docs" 2025-09-30 06:40:06.544635 | 2025-09-30 06:40:06.544748 | TASK [Check if worker can sudo] 2025-09-30 06:40:07.088447 | controller | ok: Runtime: 0:00:00.061186 2025-09-30 06:40:07.094022 | 2025-09-30 06:40:07.094085 | TASK [configure-mirrors : Gather needed facts] 2025-09-30 06:40:07.137809 | controller | skipping: Conditional result was False 2025-09-30 06:40:07.143518 | 2025-09-30 06:40:07.143583 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-09-30 06:40:07.268220 | controller | ok 2025-09-30 06:40:07.300857 | controller | included: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-09-30 06:40:07.306258 | 2025-09-30 06:40:07.306319 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-09-30 06:40:07.650227 | controller | ok 2025-09-30 06:40:07.657884 | 2025-09-30 06:40:07.657966 | LOOP [configure-mirrors : Include OS-specific variables] 2025-09-30 06:40:07.739604 | controller | ok: "/var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-09-30 06:40:07.749368 | 2025-09-30 06:40:07.749429 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-09-30 06:40:08.729951 | controller | changed 2025-09-30 06:40:08.740814 | 2025-09-30 06:40:08.740939 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-09-30 06:40:08.822359 | controller | ok: "/var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-09-30 06:40:08.822559 | controller | ok: All items complete 2025-09-30 06:40:08.822595 | 2025-09-30 06:40:08.907190 | controller | included: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-09-30 06:40:08.914570 | 2025-09-30 06:40:08.914650 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-09-30 06:40:10.047325 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-09-30 06:40:10.999345 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-09-30 06:40:11.011276 | 2025-09-30 06:40:11.011359 | TASK [configure-mirrors : Disable deltrarpm] 2025-09-30 06:40:11.480796 | controller | changed: section and option added 2025-09-30 06:40:11.542031 | 2025-09-30 06:40:11.542142 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-09-30 06:40:12.432642 | controller | 29 files removed 2025-09-30 06:40:12.432857 | controller | ok: Item: dnf clean all Runtime: 0:00:00.540391 2025-09-30 06:40:12.432896 | controller | changed: All items complete 2025-09-30 06:40:12.432917 | 2025-09-30 06:40:22.933571 | 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 06:40:22.933751 | controller | DNF version: 4.14.0 2025-09-30 06:40:22.933813 | controller | cachedir: /var/cache/dnf 2025-09-30 06:40:22.933863 | controller | Making cache files for all metadata files. 2025-09-30 06:40:22.933909 | controller | baseos: has expired and will be refreshed. 2025-09-30 06:40:22.933952 | controller | appstream: has expired and will be refreshed. 2025-09-30 06:40:22.933994 | controller | crb: has expired and will be refreshed. 2025-09-30 06:40:22.934050 | controller | extras-common: has expired and will be refreshed. 2025-09-30 06:40:22.934091 | controller | repo: downloading from remote: baseos 2025-09-30 06:40:22.934131 | controller | CentOS Stream 9 - BaseOS 71 MB/s | 8.8 MB 00:00 2025-09-30 06:40:22.934171 | controller | baseos: using metadata from Mon 22 Sep 2025 10:29:43 AM EDT. 2025-09-30 06:40:22.934211 | controller | repo: downloading from remote: appstream 2025-09-30 06:40:22.934249 | controller | CentOS Stream 9 - AppStream 100 MB/s | 25 MB 00:00 2025-09-30 06:40:22.934288 | controller | appstream: using metadata from Mon 22 Sep 2025 10:33:24 AM EDT. 2025-09-30 06:40:22.934327 | controller | repo: downloading from remote: crb 2025-09-30 06:40:22.934365 | controller | CentOS Stream 9 - CRB 85 MB/s | 7.1 MB 00:00 2025-09-30 06:40:22.934405 | controller | crb: using metadata from Mon 22 Sep 2025 10:37:51 AM EDT. 2025-09-30 06:40:22.934450 | controller | repo: downloading from remote: extras-common 2025-09-30 06:40:22.934503 | controller | CentOS Stream 9 - Extras packages 1.0 MB/s | 20 kB 00:00 2025-09-30 06:40:22.934560 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-09-30 06:40:22.934625 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-09-30 06:40:22.934764 | controller | Completion plugin: Generating completion cache... 2025-09-30 06:40:22.934852 | controller | Metadata cache created. 2025-09-30 06:40:22.934949 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.199083 2025-09-30 06:40:22.956230 | 2025-09-30 06:40:22.956335 | PLAY RECAP 2025-09-30 06:40:22.956393 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-09-30 06:40:22.956428 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-30 06:40:22.956454 | 2025-09-30 06:40:23.063793 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-09-30 06:40:23.064600 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-30 06:40:23.642805 | 2025-09-30 06:40:23.642909 | PLAY [all] 2025-09-30 06:40:23.664792 | 2025-09-30 06:40:23.664894 | TASK [Install binary dependencies] 2025-09-30 06:40:23.734764 | controller | ok 2025-09-30 06:40:23.754204 | 2025-09-30 06:40:23.754340 | TASK [bindep : Include find tasks] 2025-09-30 06:40:23.783515 | controller | ok 2025-09-30 06:40:23.794221 | controller | included: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-30 06:40:23.800572 | 2025-09-30 06:40:23.800640 | TASK [bindep : Look for bindep.txt] 2025-09-30 06:40:24.223335 | controller | ok 2025-09-30 06:40:24.237230 | 2025-09-30 06:40:24.237378 | TASK [bindep : Define bindep_file fact] 2025-09-30 06:40:24.284595 | controller | ok 2025-09-30 06:40:24.295777 | 2025-09-30 06:40:24.295916 | TASK [bindep : Look for other-requirements.txt] 2025-09-30 06:40:24.322612 | controller | skipping: Conditional result was False 2025-09-30 06:40:24.334624 | 2025-09-30 06:40:24.334799 | TASK [bindep : Define bindep_file fact] 2025-09-30 06:40:24.372547 | controller | skipping: Conditional result was False 2025-09-30 06:40:24.386238 | 2025-09-30 06:40:24.386388 | TASK [bindep : Look for bindep fallback file] 2025-09-30 06:40:24.445387 | controller | skipping: Conditional result was False 2025-09-30 06:40:24.459297 | 2025-09-30 06:40:24.459419 | TASK [bindep : Define bindep_file fact] 2025-09-30 06:40:24.484258 | controller | skipping: Conditional result was False 2025-09-30 06:40:24.490069 | 2025-09-30 06:40:24.490137 | TASK [bindep : Include bindep tasks] 2025-09-30 06:40:24.519986 | controller | ok 2025-09-30 06:40:24.527034 | controller | included: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-09-30 06:40:24.542248 | 2025-09-30 06:40:24.542389 | TASK [bindep : Look for bindep command] 2025-09-30 06:40:24.578856 | controller | skipping: Conditional result was False 2025-09-30 06:40:24.585624 | 2025-09-30 06:40:24.585716 | TASK [bindep : Check for system bindep] 2025-09-30 06:40:25.116434 | controller | ok: Runtime: 0:00:00.008610 2025-09-30 06:40:25.128348 | 2025-09-30 06:40:25.128484 | TASK [bindep : Define bindep_command fact] 2025-09-30 06:40:25.165998 | controller | skipping: Conditional result was False 2025-09-30 06:40:25.172354 | 2025-09-30 06:40:25.172420 | TASK [bindep : Include install tasks] 2025-09-30 06:40:25.218371 | controller | ok 2025-09-30 06:40:25.228802 | controller | included: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-09-30 06:40:25.241849 | 2025-09-30 06:40:25.241935 | TASK [bindep : Create temp dir for bindep] 2025-09-30 06:40:25.637599 | controller | changed 2025-09-30 06:40:25.643269 | 2025-09-30 06:40:25.643330 | TASK [Ensure we have pip dependencies] 2025-09-30 06:40:25.667997 | controller | ok 2025-09-30 06:40:25.693109 | 2025-09-30 06:40:25.693189 | TASK [ensure-pip : Check if pip is installed] 2025-09-30 02:40:26.020419 | controller | /usr/bin/pip3 2025-09-30 02:40:26.063039 | controller | /usr/bin/python3: No module named wheel 2025-09-30 06:40:26.229852 | controller | ok: Runtime: 0:00:00.059167 2025-09-30 06:40:26.238365 | 2025-09-30 06:40:26.238456 | LOOP [ensure-pip : Install pip from packages] 2025-09-30 06:40:26.266805 | controller | ok: "/var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-09-30 06:40:26.292424 | controller | included: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-09-30 06:40:26.313521 | 2025-09-30 06:40:26.313607 | TASK [ensure-pip : Install Python 3 pip] 2025-09-30 06:40:28.753344 | controller | changed 2025-09-30 06:40:28.762356 | 2025-09-30 06:40:28.762419 | TASK [ensure-pip : Check for EPEL repository] 2025-09-30 06:40:28.796113 | controller | skipping: Conditional result was False 2025-09-30 06:40:28.803266 | 2025-09-30 06:40:28.803342 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-09-30 06:40:28.842635 | controller | skipping: Conditional result was False 2025-09-30 06:40:28.850287 | 2025-09-30 06:40:28.850367 | TASK [ensure-pip : Install Python 2 pip] 2025-09-30 06:40:28.884580 | controller | skipping: Conditional result was False 2025-09-30 06:40:28.890952 | 2025-09-30 06:40:28.891018 | TASK [ensure-pip : Ensure setuptools] 2025-09-30 06:40:28.904917 | controller | skipping: Conditional result was False 2025-09-30 06:40:28.911070 | 2025-09-30 06:40:28.911132 | TASK [ensure-pip : Check for ensurepip module] 2025-09-30 06:40:29.441798 | controller | skipping: Conditional result was False 2025-09-30 06:40:29.448914 | 2025-09-30 06:40:29.448987 | TASK [ensure-pip : Ensure python3-venv] 2025-09-30 06:40:29.483147 | controller | skipping: Conditional result was False 2025-09-30 06:40:29.489486 | 2025-09-30 06:40:29.489551 | TASK [ensure-pip : Install pip from source] 2025-09-30 06:40:29.524971 | controller | skipping: Conditional result was False 2025-09-30 06:40:29.532249 | 2025-09-30 06:40:29.532345 | TASK [ensure-pip : Probe for venv python full path] 2025-09-30 02:40:29.837204 | controller | /usr/bin/python3 2025-09-30 06:40:30.090596 | controller | ok: Runtime: 0:00:00.007500 2025-09-30 06:40:30.104135 | 2025-09-30 06:40:30.104298 | TASK [ensure-pip : Set host default] 2025-09-30 06:40:30.184547 | controller | ok 2025-09-30 06:40:30.198340 | 2025-09-30 06:40:30.198540 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-09-30 06:40:30.261892 | controller | ok 2025-09-30 06:40:30.285712 | 2025-09-30 06:40:30.285864 | TASK [bindep : Install bindep into temporary venv] 2025-09-30 06:40:34.364985 | controller | changed 2025-09-30 06:40:34.378251 | 2025-09-30 06:40:34.378401 | TASK [bindep : Define bindep_command] 2025-09-30 06:40:34.419755 | controller | ok 2025-09-30 06:40:34.431113 | 2025-09-30 06:40:34.431251 | LOOP [bindep : Include package tasks] 2025-09-30 06:40:34.503063 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-09-30 06:40:34.503294 | controller | ok: All items complete 2025-09-30 06:40:34.503332 | 2025-09-30 06:40:34.523985 | controller | included: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-09-30 06:40:34.545175 | 2025-09-30 06:40:34.545266 | TASK [bindep : Define bindep_run fact] 2025-09-30 06:40:34.588978 | controller | ok 2025-09-30 06:40:34.596633 | 2025-09-30 06:40:34.596792 | TASK [bindep : Get list of packages to install from bindep] 2025-09-30 02:40:35.894661 | controller | podman 2025-09-30 02:40:35.925904 | controller | python3-jmespath 2025-09-30 02:40:35.925984 | controller | python3-libvirt 2025-09-30 02:40:35.925995 | controller | python3-lxml 2025-09-30 02:40:35.926004 | controller | python3-netaddr 2025-09-30 06:40:36.140736 | controller | ok: Runtime: 0:00:01.028489 2025-09-30 06:40:36.149253 | 2025-09-30 06:40:36.149343 | TASK [bindep : Install distro packages from bindep] 2025-09-30 06:41:36.567287 | controller | changed 2025-09-30 06:41:36.575000 | 2025-09-30 06:41:36.575066 | TASK [bindep : Check that packages are installed] 2025-09-30 06:41:38.133265 | controller | ok: Runtime: 0:00:01.017651 2025-09-30 06:41:38.139008 | 2025-09-30 06:41:38.139072 | TASK [bindep : Fail if we cannot install all packages] 2025-09-30 06:41:38.162975 | controller | skipping: Conditional result was False 2025-09-30 06:41:38.173079 | 2025-09-30 06:41:38.173142 | TASK [Run test-setup role] 2025-09-30 06:41:38.191642 | controller | ok 2025-09-30 06:41:38.208232 | 2025-09-30 06:41:38.208292 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-30 06:41:38.458302 | controller | ok 2025-09-30 06:41:38.469540 | 2025-09-30 06:41:38.469673 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-30 06:41:39.010330 | controller | skipping: Conditional result was False 2025-09-30 06:41:39.042441 | 2025-09-30 06:41:39.042627 | TASK [bindep : Remove bindep temp dir] 2025-09-30 06:41:39.400452 | controller | ok 2025-09-30 06:41:39.416990 | 2025-09-30 06:41:39.417053 | PLAY RECAP 2025-09-30 06:41:39.417095 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-09-30 06:41:39.417116 | 2025-09-30 06:41:39.510543 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-30 06:41:39.511420 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-09-30 06:41:40.239111 | 2025-09-30 06:41:40.239224 | PLAY [all] 2025-09-30 06:41:40.261942 | 2025-09-30 06:41:40.262031 | TASK [Abort when test_command variable is undefined] 2025-09-30 06:41:40.287468 | controller | skipping: Conditional result was False 2025-09-30 06:41:40.294015 | 2025-09-30 06:41:40.294093 | TASK [Convert test_command to list] 2025-09-30 06:41:40.361084 | controller | skipping: Conditional result was False 2025-09-30 06:41:40.368573 | 2025-09-30 06:41:40.368644 | TASK [Use test_command list] 2025-09-30 06:41:40.411969 | controller | ok 2025-09-30 06:41:40.420204 | 2025-09-30 06:41:40.420270 | LOOP [Run test_command] 2025-09-30 06:41:40.803177 | controller | no check to run 2025-09-30 06:41:40.803465 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.008055 2025-09-30 06:41:40.835240 | 2025-09-30 06:41:40.835305 | PLAY RECAP 2025-09-30 06:41:40.835346 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-09-30 06:41:40.835365 | 2025-09-30 06:41:40.923141 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-09-30 06:41:40.924014 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-30 06:41:41.595483 | 2025-09-30 06:41:41.595595 | PLAY [all] 2025-09-30 06:41:41.618193 | 2025-09-30 06:41:41.618346 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-30 06:41:42.016938 | controller | changed: non-zero return code 2025-09-30 06:41:42.022383 | 2025-09-30 06:41:42.022455 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-30 06:41:42.036432 | controller | skipping: Conditional result was False 2025-09-30 06:41:42.042251 | 2025-09-30 06:41:42.042318 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-30 06:41:42.063901 | 2025-09-30 06:41:42.064018 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-30 06:41:42.083610 | 2025-09-30 06:41:42.083762 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-30 06:41:42.097359 | controller | skipping: Conditional result was False 2025-09-30 06:41:42.103309 | 2025-09-30 06:41:42.103377 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-30 06:41:42.123066 | 2025-09-30 06:41:42.123195 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-30 06:41:42.138800 | controller | skipping: Conditional result was False 2025-09-30 06:41:42.144292 | 2025-09-30 06:41:42.144357 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-30 06:41:42.157837 | controller | skipping: Conditional result was False 2025-09-30 06:41:42.163649 | 2025-09-30 06:41:42.163741 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-30 06:41:42.177353 | controller | skipping: Conditional result was False 2025-09-30 06:41:42.201871 | 2025-09-30 06:41:42.201924 | PLAY RECAP 2025-09-30 06:41:42.201963 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-30 06:41:42.201982 | 2025-09-30 06:41:42.327256 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-30 06:41:42.328064 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-30 06:41:42.878756 | 2025-09-30 06:41:42.878858 | PLAY [all] 2025-09-30 06:41:42.897341 | 2025-09-30 06:41:42.897412 | TASK [include_role : fetch-output] 2025-09-30 06:41:42.926581 | controller | ok 2025-09-30 06:41:42.943272 | 2025-09-30 06:41:42.943348 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-30 06:41:42.987769 | controller | skipping: Conditional result was False 2025-09-30 06:41:42.994884 | 2025-09-30 06:41:42.994953 | TASK [fetch-output : Set log path for single node] 2025-09-30 06:41:43.034010 | controller | ok 2025-09-30 06:41:43.039127 | 2025-09-30 06:41:43.039190 | LOOP [fetch-output : Ensure local output dirs] 2025-09-30 06:41:43.441146 | controller -> localhost | ok: "/var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/work/logs" 2025-09-30 06:41:43.906794 | controller -> localhost | changed: "/var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/work/artifacts" 2025-09-30 06:41:44.169600 | controller -> localhost | changed: "/var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/work/docs" 2025-09-30 06:41:44.180348 | 2025-09-30 06:41:44.180452 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-30 06:41:45.157465 | controller | changed: .d..t...... ./ 2025-09-30 06:41:45.157653 | controller | changed: All items complete 2025-09-30 06:41:45.157700 | 2025-09-30 06:41:45.620193 | controller | changed: .d..t...... ./ 2025-09-30 06:41:46.187651 | controller | changed: .d..t...... ./ 2025-09-30 06:41:46.202321 | 2025-09-30 06:41:46.202437 | TASK [include_role : fetch-output-openshift] 2025-09-30 06:41:46.216500 | controller | skipping: Conditional result was False 2025-09-30 06:41:46.222984 | 2025-09-30 06:41:46.223056 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-30 06:41:46.655755 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.010738 2025-09-30 06:41:46.864051 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.007461 2025-09-30 06:41:46.902606 | 2025-09-30 06:41:46.902711 | PLAY [all] 2025-09-30 06:41:46.917733 | 2025-09-30 06:41:46.917797 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-09-30 06:41:47.372724 | controller | changed 2025-09-30 06:41:47.400712 | 2025-09-30 06:41:47.400814 | PLAY RECAP 2025-09-30 06:41:47.400856 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-09-30 06:41:47.400877 | 2025-09-30 06:41:47.515065 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-30 06:41:47.515878 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-09-30 06:41:48.101356 | 2025-09-30 06:41:48.101462 | PLAY [localhost] 2025-09-30 06:41:48.119755 | 2025-09-30 06:41:48.119841 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-30 06:41:48.447454 | localhost | changed 2025-09-30 06:41:48.452617 | 2025-09-30 06:41:48.452756 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-30 06:41:48.474648 | localhost | ok 2025-09-30 06:41:48.482791 | 2025-09-30 06:41:48.482861 | TASK [add-fileserver : Create SSH private key tempfile] 2025-09-30 06:41:48.835250 | localhost | changed 2025-09-30 06:41:48.840108 | 2025-09-30 06:41:48.840177 | TASK [add-fileserver : Create SSH private key from secret] 2025-09-30 06:41:49.456604 | localhost | changed 2025-09-30 06:41:49.464384 | 2025-09-30 06:41:49.464452 | TASK [add-fileserver : Add fileserver ssh key] 2025-09-30 06:41:49.867577 | localhost | Identity added: /var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/work/tmp/ansible.jhmvzwnc (/var/lib/zuul/builds/c2a60d22e8fb480baa7198881ced9df7/work/tmp/ansible.jhmvzwnc) 2025-09-30 06:41:49.867789 | localhost | ok: Runtime: 0:00:00.013005 2025-09-30 06:41:49.872125 | 2025-09-30 06:41:49.872194 | TASK [add-fileserver : Remove SSH private key from disk] 2025-09-30 06:41:50.144939 | localhost | ok: Runtime: 0:00:00.005436 2025-09-30 06:41:50.150220 | 2025-09-30 06:41:50.150287 | TASK [add-fileserver : Add fileserver to inventory] 2025-09-30 06:41:50.198148 | localhost | changed 2025-09-30 06:41:50.203203 | 2025-09-30 06:41:50.203268 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-09-30 06:41:50.611044 | localhost | changed 2025-09-30 06:41:50.645601 | 2025-09-30 06:41:50.645704 | PLAY [localhost] 2025-09-30 06:41:50.663668 | 2025-09-30 06:41:50.663790 | TASK [Generate bulk log download script] 2025-09-30 06:41:50.694487 | localhost | ok 2025-09-30 06:41:50.705987 | 2025-09-30 06:41:50.706051 | TASK [local-log-download : Check API endpoint is defined] 2025-09-30 06:41:50.743798 | localhost | ok: All assertions passed 2025-09-30 06:41:50.748293 | 2025-09-30 06:41:50.748355 | TASK [local-log-download : Create download script] 2025-09-30 06:41:51.149277 | localhost -> localhost | changed 2025-09-30 06:41:51.160979 | 2025-09-30 06:41:51.161065 | TASK [Register quick-download link] 2025-09-30 06:41:51.194293 | localhost | ok 2025-09-30 06:41:51.252029 | 2025-09-30 06:41:51.252126 | PLAY [logserver.rdoproject.org] 2025-09-30 06:41:51.262672 | 2025-09-30 06:41:51.262751 | TASK [Set zuul-log-path fact] 2025-09-30 06:41:51.289724 | logserver.rdoproject.org | ok 2025-09-30 06:41:51.302472 | 2025-09-30 06:41:51.302541 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-30 06:41:51.329134 | logserver.rdoproject.org | ok 2025-09-30 06:41:51.335582 | 2025-09-30 06:41:51.335650 | TASK [upload-logs : Create log directories] 2025-09-30 06:41:51.995951 | logserver.rdoproject.org | changed 2025-09-30 06:41:51.999478 | 2025-09-30 06:41:51.999542 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-09-30 06:41:52.325201 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.009138 2025-09-30 06:41:52.330512 | 2025-09-30 06:41:52.330577 | TASK [upload-logs : Upload logs to log server] 2025-09-30 06:41:53.053517 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-09-30 06:41:53.056519 | 2025-09-30 06:41:53.056581 | LOOP [upload-logs : Compress console log and json output] 2025-09-30 06:41:53.108944 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 06:41:53.117931 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 06:41:53.126339 | 2025-09-30 06:41:53.126479 | LOOP [upload-logs : Upload compressed console log and json output] 2025-09-30 06:41:53.188241 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 06:41:53.188473 | 2025-09-30 06:41:53.188979 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-30 06:41:53.195222 | 2025-09-30 06:41:53.195343 | LOOP [upload-logs : Upload console log and json output]