2025-10-13 14:44:48.232655 | Job console starting... 2025-10-13 14:44:48.248384 | Updating repositories 2025-10-13 14:44:48.281327 | Preparing job workspace 2025-10-13 14:44:52.941507 | Running Ansible setup... 2025-10-13 14:44:57.187933 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-13 14:45:00.736853 | 2025-10-13 14:45:00.736974 | PLAY [localhost] 2025-10-13 14:45:00.755573 | 2025-10-13 14:45:00.757435 | TASK [Gathering Facts] 2025-10-13 14:45:02.013619 | localhost | ok 2025-10-13 14:45:02.040290 | 2025-10-13 14:45:02.040696 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-13 14:45:02.524142 | localhost -> localhost | changed 2025-10-13 14:45:02.529788 | 2025-10-13 14:45:02.529860 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-13 14:45:03.655481 | localhost -> localhost | changed 2025-10-13 14:45:03.664713 | 2025-10-13 14:45:03.664801 | TASK [Setup log path fact] 2025-10-13 14:45:03.683087 | localhost | ok 2025-10-13 14:45:03.695970 | 2025-10-13 14:45:03.696054 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-13 14:45:03.755893 | localhost | ok 2025-10-13 14:45:03.768215 | 2025-10-13 14:45:03.768312 | TASK [emit-job-header : Print job information] 2025-10-13 14:45:03.806899 | # Job Information 2025-10-13 14:45:03.807128 | Ansible Version: 2.15.12 2025-10-13 14:45:03.807156 | Job: cifmw-molecule-cifmw_external_dns 2025-10-13 14:45:03.807176 | Pipeline: github-check 2025-10-13 14:45:03.807194 | Executor: ze04.softwarefactory-project.io 2025-10-13 14:45:03.807212 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3402 2025-10-13 14:45:03.807230 | Log URL (when completed): https://logserver.rdoproject.org/8d1/rdoproject.org/8d11898d9d344006b8fd223989250f48/ 2025-10-13 14:45:03.807248 | Event ID: f7c86a20-a842-11f0-8f69-fd957689b554 2025-10-13 14:45:03.812622 | 2025-10-13 14:45:03.812723 | LOOP [emit-job-header : Print node information] 2025-10-13 14:45:03.956199 | localhost | ok: 2025-10-13 14:45:03.956362 | localhost | # Node Information 2025-10-13 14:45:03.956389 | localhost | Inventory Hostname: controller 2025-10-13 14:45:03.956411 | localhost | Hostname: np0005485185 2025-10-13 14:45:03.956431 | localhost | Username: zuul 2025-10-13 14:45:03.956452 | localhost | Distro: CentOS 9 2025-10-13 14:45:03.956471 | localhost | Provider: vexxhost-nodepool-tripleo 2025-10-13 14:45:03.956488 | localhost | Region: RegionOne 2025-10-13 14:45:03.956506 | localhost | Label: cloud-centos-9-stream-tripleo 2025-10-13 14:45:03.956522 | localhost | Product Name: OpenStack Nova 2025-10-13 14:45:03.956539 | localhost | Interface IP: 38.129.56.73 2025-10-13 14:45:03.982932 | 2025-10-13 14:45:03.983061 | PLAY [all] 2025-10-13 14:45:03.989856 | 2025-10-13 14:45:03.989919 | TASK [Gather network facts] 2025-10-13 14:45:04.533000 | controller | ok 2025-10-13 14:45:04.554506 | 2025-10-13 14:45:04.554619 | TASK [include_role : start-zuul-console] 2025-10-13 14:45:04.579587 | controller | ok 2025-10-13 14:45:04.609735 | 2025-10-13 14:45:04.609847 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-13 14:45:05.050803 | controller | ok 2025-10-13 14:45:05.069521 | 2025-10-13 14:45:05.069704 | TASK [include_role : add-build-sshkey] 2025-10-13 14:45:05.102348 | controller | ok 2025-10-13 14:45:05.124997 | 2025-10-13 14:45:05.125096 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-13 14:45:05.509806 | controller -> localhost | ok 2025-10-13 14:45:05.515108 | 2025-10-13 14:45:05.515181 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-13 14:45:05.542929 | controller | ok 2025-10-13 14:45:05.557533 | controller | included: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-13 14:45:05.565970 | 2025-10-13 14:45:05.566067 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-13 14:45:06.624906 | controller -> localhost | Generating public/private rsa key pair. 2025-10-13 14:45:06.625104 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/work/8d11898d9d344006b8fd223989250f48_id_rsa. 2025-10-13 14:45:06.625135 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/work/8d11898d9d344006b8fd223989250f48_id_rsa.pub. 2025-10-13 14:45:06.625156 | controller -> localhost | The key fingerprint is: 2025-10-13 14:45:06.625175 | controller -> localhost | SHA256:34SUMgv5+efmMZnlhfqNMH2KXgrVDnKH3v9W/QHiXc4 zuul-build-sshkey 2025-10-13 14:45:06.625193 | controller -> localhost | The key's randomart image is: 2025-10-13 14:45:06.625211 | controller -> localhost | +---[RSA 3072]----+ 2025-10-13 14:45:06.625228 | controller -> localhost | | | 2025-10-13 14:45:06.625246 | controller -> localhost | | . . | 2025-10-13 14:45:06.625264 | controller -> localhost | | o o o | 2025-10-13 14:45:06.625282 | controller -> localhost | | o * o + o | 2025-10-13 14:45:06.625299 | controller -> localhost | | S + O X o| 2025-10-13 14:45:06.625316 | controller -> localhost | | o O & Eo| 2025-10-13 14:45:06.625333 | controller -> localhost | | + % * =| 2025-10-13 14:45:06.625350 | controller -> localhost | | +.X *o| 2025-10-13 14:45:06.625368 | controller -> localhost | | +* +.=| 2025-10-13 14:45:06.625385 | controller -> localhost | +----[SHA256]-----+ 2025-10-13 14:45:06.625428 | controller -> localhost | ok: Runtime: 0:00:00.364821 2025-10-13 14:45:06.631207 | 2025-10-13 14:45:06.631273 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-13 14:45:06.651255 | controller | ok 2025-10-13 14:45:06.666223 | controller | included: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-13 14:45:06.674832 | 2025-10-13 14:45:06.674895 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-13 14:45:06.688485 | controller | skipping: Conditional result was False 2025-10-13 14:45:06.695051 | 2025-10-13 14:45:06.695135 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-13 14:45:07.204877 | controller | changed 2025-10-13 14:45:07.210436 | 2025-10-13 14:45:07.210517 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-13 14:45:07.545944 | controller | ok 2025-10-13 14:45:07.550861 | 2025-10-13 14:45:07.550924 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-13 14:45:08.603218 | controller | changed 2025-10-13 14:45:08.612651 | 2025-10-13 14:45:08.612776 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-13 14:45:09.579662 | controller | changed 2025-10-13 14:45:09.584996 | 2025-10-13 14:45:09.585086 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-13 14:45:09.619387 | controller | skipping: Conditional result was False 2025-10-13 14:45:09.630165 | 2025-10-13 14:45:09.630284 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-13 14:45:10.292702 | controller -> localhost | changed 2025-10-13 14:45:10.302902 | 2025-10-13 14:45:10.302970 | TASK [add-build-sshkey : Add back temp key] 2025-10-13 14:45:10.996616 | controller -> localhost | Identity added: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/work/8d11898d9d344006b8fd223989250f48_id_rsa (zuul-build-sshkey) 2025-10-13 14:45:10.996868 | controller -> localhost | ok: Runtime: 0:00:00.032452 2025-10-13 14:45:11.020056 | 2025-10-13 14:45:11.020169 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-13 14:45:11.588320 | controller | ok 2025-10-13 14:45:11.594571 | 2025-10-13 14:45:11.594639 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-13 14:45:11.637532 | controller | skipping: Conditional result was False 2025-10-13 14:45:11.654509 | 2025-10-13 14:45:11.654632 | TASK [include_role : validate-host] 2025-10-13 14:45:11.696602 | controller | ok 2025-10-13 14:45:11.855021 | 2025-10-13 14:45:11.855153 | TASK [validate-host : Define zuul_info_dir fact] 2025-10-13 14:45:11.949189 | controller | ok 2025-10-13 14:45:11.955365 | 2025-10-13 14:45:11.955436 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-10-13 14:45:12.540627 | controller -> localhost | ok 2025-10-13 14:45:12.546656 | 2025-10-13 14:45:12.546750 | TASK [validate-host : Collect information about the host] 2025-10-13 14:45:13.340205 | controller | ok 2025-10-13 14:45:13.364334 | 2025-10-13 14:45:13.364443 | TASK [validate-host : Sanitize hostname] 2025-10-13 14:45:13.584845 | controller | ok 2025-10-13 14:45:13.609182 | 2025-10-13 14:45:13.609900 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-10-13 14:45:14.443614 | controller -> localhost | changed 2025-10-13 14:45:14.454475 | 2025-10-13 14:45:14.454591 | TASK [validate-host : Collect information about zuul worker] 2025-10-13 14:45:15.215557 | controller | ok 2025-10-13 14:45:15.221873 | 2025-10-13 14:45:15.221945 | TASK [validate-host : Write out all zuul information for each host] 2025-10-13 14:45:16.620285 | controller -> localhost | changed 2025-10-13 14:45:16.657768 | 2025-10-13 14:45:16.657890 | TASK [include_role : prepare-workspace-openshift] 2025-10-13 14:45:16.713731 | controller | skipping: Conditional result was False 2025-10-13 14:45:16.720269 | 2025-10-13 14:45:16.720357 | TASK [include_role : remove-zuul-sshkey] 2025-10-13 14:45:16.783262 | controller | skipping: Conditional result was False 2025-10-13 14:45:16.789480 | 2025-10-13 14:45:16.789589 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-13 14:45:17.150761 | controller | ok: "logs" 2025-10-13 14:45:17.150988 | controller | ok: All items complete 2025-10-13 14:45:17.151017 | 2025-10-13 14:45:17.386852 | controller | ok: "artifacts" 2025-10-13 14:45:17.646398 | controller | ok: "docs" 2025-10-13 14:45:17.654820 | 2025-10-13 14:45:17.654933 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-13 14:45:18.038188 | controller | changed: "logs" 2025-10-13 14:45:18.335442 | controller | changed: "artifacts" 2025-10-13 14:45:18.634715 | controller | changed: "docs" 2025-10-13 14:45:18.683811 | 2025-10-13 14:45:18.683895 | PLAY RECAP 2025-10-13 14:45:18.683938 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-13 14:45:18.683963 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-13 14:45:18.683980 | 2025-10-13 14:45:18.881157 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-13 14:45:18.881967 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-13 14:45:20.159452 | 2025-10-13 14:45:20.159558 | PLAY [localhost] 2025-10-13 14:45:20.179605 | 2025-10-13 14:45:20.179718 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-10-13 14:45:20.792410 | localhost | ok 2025-10-13 14:45:20.800285 | 2025-10-13 14:45:20.800588 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-10-13 14:45:22.195890 | localhost | changed 2025-10-13 14:45:22.230312 | 2025-10-13 14:45:22.231062 | PLAY [all] 2025-10-13 14:45:22.255810 | 2025-10-13 14:45:22.255912 | TASK [include_role : prepare-workspace] 2025-10-13 14:45:22.299562 | controller | ok 2025-10-13 14:45:22.332317 | 2025-10-13 14:45:22.332440 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-13 14:45:22.824170 | controller | ok 2025-10-13 14:45:22.830245 | 2025-10-13 14:45:22.830309 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-13 14:45:25.177856 | controller | Output suppressed because no_log was given 2025-10-13 14:45:25.191943 | 2025-10-13 14:45:25.192062 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-13 14:45:25.485602 | controller | changed: "logs" 2025-10-13 14:45:25.745757 | controller | changed: "artifacts" 2025-10-13 14:45:25.986075 | controller | changed: "docs" 2025-10-13 14:45:25.997449 | 2025-10-13 14:45:25.997599 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-13 14:45:26.379326 | controller | changed: "logs" 2025-10-13 14:45:26.379561 | controller | changed: All items complete 2025-10-13 14:45:26.379589 | 2025-10-13 14:45:26.660564 | controller | changed: "artifacts" 2025-10-13 14:45:26.893979 | controller | changed: "docs" 2025-10-13 14:45:26.917375 | 2025-10-13 14:45:26.917503 | TASK [Check if worker can sudo] 2025-10-13 14:45:27.959197 | controller | ok: Runtime: 0:00:00.059851 2025-10-13 14:45:27.968946 | 2025-10-13 14:45:27.969028 | TASK [configure-mirrors : Gather needed facts] 2025-10-13 14:45:28.065949 | controller | skipping: Conditional result was False 2025-10-13 14:45:28.103489 | 2025-10-13 14:45:28.103625 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-10-13 14:45:28.163720 | controller | ok 2025-10-13 14:45:28.177837 | controller | included: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-10-13 14:45:28.184874 | 2025-10-13 14:45:28.184964 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-10-13 14:45:28.490945 | controller | ok 2025-10-13 14:45:28.522662 | 2025-10-13 14:45:28.522839 | LOOP [configure-mirrors : Include OS-specific variables] 2025-10-13 14:45:28.650587 | controller | ok: "/var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-10-13 14:45:28.664656 | 2025-10-13 14:45:28.664914 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-10-13 14:45:29.656631 | controller | changed 2025-10-13 14:45:29.665520 | 2025-10-13 14:45:29.665591 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-10-13 14:45:29.752633 | controller | ok: "/var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-10-13 14:45:29.753172 | controller | ok: All items complete 2025-10-13 14:45:29.753241 | 2025-10-13 14:45:29.816372 | controller | included: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-10-13 14:45:29.823386 | 2025-10-13 14:45:29.823456 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-10-13 14:45:30.984709 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-10-13 14:45:31.872752 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-10-13 14:45:31.882733 | 2025-10-13 14:45:31.882854 | TASK [configure-mirrors : Disable deltrarpm] 2025-10-13 14:45:32.408064 | controller | changed: section and option added 2025-10-13 14:45:32.437963 | 2025-10-13 14:45:32.438129 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-10-13 14:45:33.256031 | controller | 29 files removed 2025-10-13 14:45:33.256222 | controller | ok: Item: dnf clean all Runtime: 0:00:00.475329 2025-10-13 14:45:33.256262 | controller | changed: All items complete 2025-10-13 14:45:33.256284 | 2025-10-13 14:45:44.010301 | 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:45:44.010406 | controller | DNF version: 4.14.0 2025-10-13 14:45:44.010431 | controller | cachedir: /var/cache/dnf 2025-10-13 14:45:44.010453 | controller | Making cache files for all metadata files. 2025-10-13 14:45:44.010570 | controller | baseos: has expired and will be refreshed. 2025-10-13 14:45:44.010617 | controller | appstream: has expired and will be refreshed. 2025-10-13 14:45:44.010638 | controller | crb: has expired and will be refreshed. 2025-10-13 14:45:44.010666 | controller | extras-common: has expired and will be refreshed. 2025-10-13 14:45:44.010709 | controller | repo: downloading from remote: baseos 2025-10-13 14:45:44.010730 | controller | CentOS Stream 9 - BaseOS 63 MB/s | 8.8 MB 00:00 2025-10-13 14:45:44.010748 | controller | baseos: using metadata from Wed 08 Oct 2025 09:42:12 AM EDT. 2025-10-13 14:45:44.010766 | controller | repo: downloading from remote: appstream 2025-10-13 14:45:44.010784 | controller | CentOS Stream 9 - AppStream 75 MB/s | 25 MB 00:00 2025-10-13 14:45:44.010801 | controller | appstream: using metadata from Wed 08 Oct 2025 09:45:45 AM EDT. 2025-10-13 14:45:44.010819 | controller | repo: downloading from remote: crb 2025-10-13 14:45:44.010836 | controller | CentOS Stream 9 - CRB 55 MB/s | 7.2 MB 00:00 2025-10-13 14:45:44.010854 | controller | crb: using metadata from Wed 08 Oct 2025 09:50:07 AM EDT. 2025-10-13 14:45:44.010871 | controller | repo: downloading from remote: extras-common 2025-10-13 14:45:44.010889 | controller | CentOS Stream 9 - Extras packages 1.6 MB/s | 20 kB 00:00 2025-10-13 14:45:44.010906 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-10-13 14:45:44.011032 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-10-13 14:45:44.011053 | controller | Completion plugin: Generating completion cache... 2025-10-13 14:45:44.011072 | controller | Metadata cache created. 2025-10-13 14:45:44.011099 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.483013 2025-10-13 14:45:44.078866 | 2025-10-13 14:45:44.078964 | PLAY RECAP 2025-10-13 14:45:44.079003 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-13 14:45:44.079029 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-13 14:45:44.079047 | 2025-10-13 14:45:44.225132 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-13 14:45:44.225943 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-13 14:45:44.800496 | 2025-10-13 14:45:44.800603 | PLAY [all] 2025-10-13 14:45:44.834747 | 2025-10-13 14:45:44.834852 | TASK [Install binary dependencies] 2025-10-13 14:45:44.936376 | controller | ok 2025-10-13 14:45:44.958902 | 2025-10-13 14:45:44.959042 | TASK [bindep : Include find tasks] 2025-10-13 14:45:44.987891 | controller | ok 2025-10-13 14:45:45.010910 | controller | included: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-13 14:45:45.017758 | 2025-10-13 14:45:45.017835 | TASK [bindep : Look for bindep.txt] 2025-10-13 14:45:45.417044 | controller | ok 2025-10-13 14:45:45.424189 | 2025-10-13 14:45:45.424260 | TASK [bindep : Define bindep_file fact] 2025-10-13 14:45:45.454177 | controller | ok 2025-10-13 14:45:45.459921 | 2025-10-13 14:45:45.459990 | TASK [bindep : Look for other-requirements.txt] 2025-10-13 14:45:45.473948 | controller | skipping: Conditional result was False 2025-10-13 14:45:45.481237 | 2025-10-13 14:45:45.481328 | TASK [bindep : Define bindep_file fact] 2025-10-13 14:45:45.510011 | controller | skipping: Conditional result was False 2025-10-13 14:45:45.517063 | 2025-10-13 14:45:45.517137 | TASK [bindep : Look for bindep fallback file] 2025-10-13 14:45:45.561642 | controller | skipping: Conditional result was False 2025-10-13 14:45:45.568543 | 2025-10-13 14:45:45.568621 | TASK [bindep : Define bindep_file fact] 2025-10-13 14:45:45.594831 | controller | skipping: Conditional result was False 2025-10-13 14:45:45.600588 | 2025-10-13 14:45:45.600658 | TASK [bindep : Include bindep tasks] 2025-10-13 14:45:45.642663 | controller | ok 2025-10-13 14:45:45.652559 | controller | included: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-10-13 14:45:45.663764 | 2025-10-13 14:45:45.663885 | TASK [bindep : Look for bindep command] 2025-10-13 14:45:45.693541 | controller | skipping: Conditional result was False 2025-10-13 14:45:45.700573 | 2025-10-13 14:45:45.700651 | TASK [bindep : Check for system bindep] 2025-10-13 14:45:46.247738 | controller | ok: Runtime: 0:00:00.006951 2025-10-13 14:45:46.255846 | 2025-10-13 14:45:46.255952 | TASK [bindep : Define bindep_command fact] 2025-10-13 14:45:46.300116 | controller | skipping: Conditional result was False 2025-10-13 14:45:46.308519 | 2025-10-13 14:45:46.308634 | TASK [bindep : Include install tasks] 2025-10-13 14:45:46.361573 | controller | ok 2025-10-13 14:45:46.370643 | controller | included: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-10-13 14:45:46.384281 | 2025-10-13 14:45:46.384741 | TASK [bindep : Create temp dir for bindep] 2025-10-13 14:45:46.824130 | controller | changed 2025-10-13 14:45:46.832272 | 2025-10-13 14:45:46.832359 | TASK [Ensure we have pip dependencies] 2025-10-13 14:45:46.854778 | controller | ok 2025-10-13 14:45:46.892759 | 2025-10-13 14:45:46.892908 | TASK [ensure-pip : Check if pip is installed] 2025-10-13 10:45:47.175629 | controller | /usr/bin/pip3 2025-10-13 10:45:47.202815 | controller | /usr/bin/python3: No module named wheel 2025-10-13 14:45:47.425150 | controller | ok: Runtime: 0:00:00.039509 2025-10-13 14:45:47.444131 | 2025-10-13 14:45:47.444369 | LOOP [ensure-pip : Install pip from packages] 2025-10-13 14:45:47.512559 | controller | ok: "/var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-10-13 14:45:47.529390 | controller | included: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-10-13 14:45:47.544328 | 2025-10-13 14:45:47.544540 | TASK [ensure-pip : Install Python 3 pip] 2025-10-13 14:45:49.971808 | controller | changed 2025-10-13 14:45:49.977250 | 2025-10-13 14:45:49.977328 | TASK [ensure-pip : Check for EPEL repository] 2025-10-13 14:45:50.043620 | controller | skipping: Conditional result was False 2025-10-13 14:45:50.049925 | 2025-10-13 14:45:50.050002 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-10-13 14:45:50.095248 | controller | skipping: Conditional result was False 2025-10-13 14:45:50.101661 | 2025-10-13 14:45:50.101751 | TASK [ensure-pip : Install Python 2 pip] 2025-10-13 14:45:50.157485 | controller | skipping: Conditional result was False 2025-10-13 14:45:50.174620 | 2025-10-13 14:45:50.174811 | TASK [ensure-pip : Ensure setuptools] 2025-10-13 14:45:50.214293 | controller | skipping: Conditional result was False 2025-10-13 14:45:50.220931 | 2025-10-13 14:45:50.221002 | TASK [ensure-pip : Check for ensurepip module] 2025-10-13 14:45:50.762535 | controller | skipping: Conditional result was False 2025-10-13 14:45:50.797084 | 2025-10-13 14:45:50.797325 | TASK [ensure-pip : Ensure python3-venv] 2025-10-13 14:45:50.825824 | controller | skipping: Conditional result was False 2025-10-13 14:45:50.832183 | 2025-10-13 14:45:50.832248 | TASK [ensure-pip : Install pip from source] 2025-10-13 14:45:50.846890 | controller | skipping: Conditional result was False 2025-10-13 14:45:50.854034 | 2025-10-13 14:45:50.854115 | TASK [ensure-pip : Probe for venv python full path] 2025-10-13 10:45:51.158845 | controller | /usr/bin/python3 2025-10-13 14:45:51.390884 | controller | ok: Runtime: 0:00:00.005241 2025-10-13 14:45:51.396881 | 2025-10-13 14:45:51.396954 | TASK [ensure-pip : Set host default] 2025-10-13 14:45:51.444979 | controller | ok 2025-10-13 14:45:51.450536 | 2025-10-13 14:45:51.450599 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-10-13 14:45:51.493376 | controller | ok 2025-10-13 14:45:51.503446 | 2025-10-13 14:45:51.503508 | TASK [bindep : Install bindep into temporary venv] 2025-10-13 14:45:55.799354 | controller | changed 2025-10-13 14:45:55.813212 | 2025-10-13 14:45:55.813368 | TASK [bindep : Define bindep_command] 2025-10-13 14:45:55.849563 | controller | ok 2025-10-13 14:45:55.859953 | 2025-10-13 14:45:55.860095 | LOOP [bindep : Include package tasks] 2025-10-13 14:45:55.917743 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-10-13 14:45:55.917965 | controller | ok: All items complete 2025-10-13 14:45:55.917993 | 2025-10-13 14:45:55.935546 | controller | included: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-10-13 14:45:55.945542 | 2025-10-13 14:45:55.945613 | TASK [bindep : Define bindep_run fact] 2025-10-13 14:45:55.974068 | controller | ok 2025-10-13 14:45:55.979264 | 2025-10-13 14:45:55.979325 | TASK [bindep : Get list of packages to install from bindep] 2025-10-13 10:45:57.326838 | controller | podman 2025-10-13 10:45:57.363910 | controller | python3-jmespath 2025-10-13 10:45:57.363978 | controller | python3-libvirt 2025-10-13 10:45:57.363989 | controller | python3-lxml 2025-10-13 10:45:57.364090 | controller | python3-netaddr 2025-10-13 14:45:57.511791 | controller | ok: Runtime: 0:00:01.138636 2025-10-13 14:45:57.524306 | 2025-10-13 14:45:57.524450 | TASK [bindep : Install distro packages from bindep] 2025-10-13 14:46:59.888124 | controller | changed 2025-10-13 14:46:59.921362 | 2025-10-13 14:46:59.921593 | TASK [bindep : Check that packages are installed] 2025-10-13 14:47:01.482380 | controller | ok: Runtime: 0:00:01.097978 2025-10-13 14:47:01.488576 | 2025-10-13 14:47:01.488695 | TASK [bindep : Fail if we cannot install all packages] 2025-10-13 14:47:01.524176 | controller | skipping: Conditional result was False 2025-10-13 14:47:01.535197 | 2025-10-13 14:47:01.535275 | TASK [Run test-setup role] 2025-10-13 14:47:01.554164 | controller | ok 2025-10-13 14:47:01.571536 | 2025-10-13 14:47:01.571637 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-13 14:47:01.840738 | controller | ok 2025-10-13 14:47:01.853901 | 2025-10-13 14:47:01.854083 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-13 14:47:02.401626 | controller | skipping: Conditional result was False 2025-10-13 14:47:02.455192 | 2025-10-13 14:47:02.455333 | TASK [bindep : Remove bindep temp dir] 2025-10-13 14:47:02.881489 | controller | ok 2025-10-13 14:47:02.905259 | 2025-10-13 14:47:02.905386 | PLAY RECAP 2025-10-13 14:47:02.905463 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-10-13 14:47:02.905507 | 2025-10-13 14:47:03.027158 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-13 14:47:03.028117 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-13 14:47:03.598855 | 2025-10-13 14:47:03.598966 | PLAY [all] 2025-10-13 14:47:03.619897 | 2025-10-13 14:47:03.619988 | TASK [Abort when test_command variable is undefined] 2025-10-13 14:47:03.653498 | controller | skipping: Conditional result was False 2025-10-13 14:47:03.660250 | 2025-10-13 14:47:03.660334 | TASK [Convert test_command to list] 2025-10-13 14:47:03.694455 | controller | skipping: Conditional result was False 2025-10-13 14:47:03.701783 | 2025-10-13 14:47:03.701866 | TASK [Use test_command list] 2025-10-13 14:47:03.750402 | controller | ok 2025-10-13 14:47:03.756123 | 2025-10-13 14:47:03.756221 | LOOP [Run test_command] 2025-10-13 14:47:04.187957 | controller | no check to run 2025-10-13 14:47:04.188407 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.006024 2025-10-13 14:47:04.218203 | 2025-10-13 14:47:04.218310 | PLAY RECAP 2025-10-13 14:47:04.218351 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-13 14:47:04.218372 | 2025-10-13 14:47:04.310239 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-13 14:47:04.311094 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-13 14:47:04.877877 | 2025-10-13 14:47:04.877987 | PLAY [all] 2025-10-13 14:47:04.898142 | 2025-10-13 14:47:04.898224 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-13 14:47:05.298348 | controller | changed: non-zero return code 2025-10-13 14:47:05.303971 | 2025-10-13 14:47:05.304046 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-13 14:47:05.318085 | controller | skipping: Conditional result was False 2025-10-13 14:47:05.323761 | 2025-10-13 14:47:05.323829 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-13 14:47:05.343414 | 2025-10-13 14:47:05.343563 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-13 14:47:05.362791 | 2025-10-13 14:47:05.362948 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-13 14:47:05.376912 | controller | skipping: Conditional result was False 2025-10-13 14:47:05.382969 | 2025-10-13 14:47:05.383040 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-13 14:47:05.402088 | 2025-10-13 14:47:05.402235 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-13 14:47:05.417122 | controller | skipping: Conditional result was False 2025-10-13 14:47:05.422818 | 2025-10-13 14:47:05.422886 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-13 14:47:05.436113 | controller | skipping: Conditional result was False 2025-10-13 14:47:05.442358 | 2025-10-13 14:47:05.442426 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-13 14:47:05.455779 | controller | skipping: Conditional result was False 2025-10-13 14:47:05.481444 | 2025-10-13 14:47:05.481524 | PLAY RECAP 2025-10-13 14:47:05.481569 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-13 14:47:05.481591 | 2025-10-13 14:47:05.573254 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-13 14:47:05.574153 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-13 14:47:06.221313 | 2025-10-13 14:47:06.221474 | PLAY [all] 2025-10-13 14:47:06.240932 | 2025-10-13 14:47:06.241049 | TASK [include_role : fetch-output] 2025-10-13 14:47:06.289924 | controller | ok 2025-10-13 14:47:06.308261 | 2025-10-13 14:47:06.308380 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-13 14:47:06.372881 | controller | skipping: Conditional result was False 2025-10-13 14:47:06.378641 | 2025-10-13 14:47:06.378743 | TASK [fetch-output : Set log path for single node] 2025-10-13 14:47:06.417460 | controller | ok 2025-10-13 14:47:06.422490 | 2025-10-13 14:47:06.422573 | LOOP [fetch-output : Ensure local output dirs] 2025-10-13 14:47:06.887743 | controller -> localhost | ok: "/var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/work/logs" 2025-10-13 14:47:07.106661 | controller -> localhost | changed: "/var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/work/artifacts" 2025-10-13 14:47:07.314108 | controller -> localhost | changed: "/var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/work/docs" 2025-10-13 14:47:07.332036 | 2025-10-13 14:47:07.332191 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-13 14:47:07.959410 | controller | changed: .d..t...... ./ 2025-10-13 14:47:07.960052 | controller | changed: All items complete 2025-10-13 14:47:07.960128 | 2025-10-13 14:47:08.464977 | controller | changed: .d..t...... ./ 2025-10-13 14:47:08.962709 | controller | changed: .d..t...... ./ 2025-10-13 14:47:08.976349 | 2025-10-13 14:47:08.976477 | TASK [include_role : fetch-output-openshift] 2025-10-13 14:47:09.000939 | controller | skipping: Conditional result was False 2025-10-13 14:47:09.007669 | 2025-10-13 14:47:09.007768 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-13 14:47:09.444348 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.010337 2025-10-13 14:47:09.700040 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.009691 2025-10-13 14:47:09.734346 | 2025-10-13 14:47:09.734462 | PLAY [all] 2025-10-13 14:47:09.750108 | 2025-10-13 14:47:09.750437 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-10-13 14:47:10.213295 | controller | changed 2025-10-13 14:47:10.238592 | 2025-10-13 14:47:10.238845 | PLAY RECAP 2025-10-13 14:47:10.238903 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-13 14:47:10.238933 | 2025-10-13 14:47:10.455264 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-13 14:47:10.456989 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-10-13 14:47:11.219374 | 2025-10-13 14:47:11.219556 | PLAY [localhost] 2025-10-13 14:47:11.242698 | 2025-10-13 14:47:11.242960 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-13 14:47:11.642272 | localhost | changed 2025-10-13 14:47:11.649016 | 2025-10-13 14:47:11.649175 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-13 14:47:11.679261 | localhost | ok 2025-10-13 14:47:11.687387 | 2025-10-13 14:47:11.687459 | TASK [add-fileserver : Create SSH private key tempfile] 2025-10-13 14:47:12.061019 | localhost | changed 2025-10-13 14:47:12.067487 | 2025-10-13 14:47:12.067578 | TASK [add-fileserver : Create SSH private key from secret] 2025-10-13 14:47:12.724252 | localhost | changed 2025-10-13 14:47:12.729456 | 2025-10-13 14:47:12.729531 | TASK [add-fileserver : Add fileserver ssh key] 2025-10-13 14:47:13.154565 | localhost | Identity added: /var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/work/tmp/ansible.cxnqxkdh (/var/lib/zuul/builds/8d11898d9d344006b8fd223989250f48/work/tmp/ansible.cxnqxkdh) 2025-10-13 14:47:13.154784 | localhost | ok: Runtime: 0:00:00.011111 2025-10-13 14:47:13.162386 | 2025-10-13 14:47:13.162466 | TASK [add-fileserver : Remove SSH private key from disk] 2025-10-13 14:47:13.419414 | localhost | ok: Runtime: 0:00:00.005188 2025-10-13 14:47:13.426300 | 2025-10-13 14:47:13.426387 | TASK [add-fileserver : Add fileserver to inventory] 2025-10-13 14:47:13.475328 | localhost | changed 2025-10-13 14:47:13.479700 | 2025-10-13 14:47:13.479763 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-10-13 14:47:13.860734 | localhost | changed 2025-10-13 14:47:13.883477 | 2025-10-13 14:47:13.883561 | PLAY [localhost] 2025-10-13 14:47:13.894935 | 2025-10-13 14:47:13.895010 | TASK [Generate bulk log download script] 2025-10-13 14:47:13.914025 | localhost | ok 2025-10-13 14:47:13.925836 | 2025-10-13 14:47:13.925899 | TASK [local-log-download : Check API endpoint is defined] 2025-10-13 14:47:13.963783 | localhost | ok: All assertions passed 2025-10-13 14:47:13.968349 | 2025-10-13 14:47:13.968411 | TASK [local-log-download : Create download script] 2025-10-13 14:47:14.347188 | localhost -> localhost | changed 2025-10-13 14:47:14.355846 | 2025-10-13 14:47:14.355909 | TASK [Register quick-download link] 2025-10-13 14:47:14.372784 | localhost | ok 2025-10-13 14:47:14.414570 | 2025-10-13 14:47:14.414661 | PLAY [logserver.rdoproject.org] 2025-10-13 14:47:14.424918 | 2025-10-13 14:47:14.425009 | TASK [Set zuul-log-path fact] 2025-10-13 14:47:14.442184 | logserver.rdoproject.org | ok 2025-10-13 14:47:14.452926 | 2025-10-13 14:47:14.453177 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-13 14:47:14.500557 | logserver.rdoproject.org | ok 2025-10-13 14:47:14.506250 | 2025-10-13 14:47:14.506315 | TASK [upload-logs : Create log directories] 2025-10-13 14:47:15.122227 | logserver.rdoproject.org | changed 2025-10-13 14:47:15.129854 | 2025-10-13 14:47:15.129949 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-10-13 14:47:15.411815 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.007107 2025-10-13 14:47:15.421423 | 2025-10-13 14:47:15.421567 | TASK [upload-logs : Upload logs to log server] 2025-10-13 14:47:16.121590 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-10-13 14:47:16.124986 | 2025-10-13 14:47:16.125062 | LOOP [upload-logs : Compress console log and json output] 2025-10-13 14:47:16.171123 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 14:47:16.180510 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 14:47:16.193307 | 2025-10-13 14:47:16.193373 | LOOP [upload-logs : Upload compressed console log and json output] 2025-10-13 14:47:16.235095 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 14:47:16.235514 | 2025-10-13 14:47:16.238799 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-13 14:47:16.255407 | 2025-10-13 14:47:16.255544 | LOOP [upload-logs : Upload console log and json output]