2025-09-29 16:03:10.160401 | Job console starting... 2025-09-29 16:03:10.174783 | Updating repositories 2025-09-29 16:03:10.220147 | Preparing job workspace 2025-09-29 16:03:13.681670 | Running Ansible setup... 2025-09-29 16:03:17.577627 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-29 16:03:18.227423 | 2025-09-29 16:03:18.227557 | PLAY [localhost] 2025-09-29 16:03:18.236676 | 2025-09-29 16:03:18.236791 | TASK [Gathering Facts] 2025-09-29 16:03:19.382820 | localhost | ok 2025-09-29 16:03:19.400128 | 2025-09-29 16:03:19.400273 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-29 16:03:19.899612 | localhost -> localhost | changed 2025-09-29 16:03:19.906308 | 2025-09-29 16:03:19.906429 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-29 16:03:20.825991 | localhost -> localhost | changed 2025-09-29 16:03:20.836326 | 2025-09-29 16:03:20.836399 | TASK [Setup log path fact] 2025-09-29 16:03:20.854305 | localhost | ok 2025-09-29 16:03:20.866859 | 2025-09-29 16:03:20.866938 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-29 16:03:20.905315 | localhost | ok 2025-09-29 16:03:20.913782 | 2025-09-29 16:03:20.913846 | TASK [emit-job-header : Print job information] 2025-09-29 16:03:20.953325 | # Job Information 2025-09-29 16:03:20.953566 | Ansible Version: 2.15.12 2025-09-29 16:03:20.953599 | Job: cifmw-molecule-recognize_ssh_keypair 2025-09-29 16:03:20.953620 | Pipeline: github-check 2025-09-29 16:03:20.953638 | Executor: ze03.softwarefactory-project.io 2025-09-29 16:03:20.953655 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3333 2025-09-29 16:03:20.953674 | Log URL (when completed): https://logserver.rdoproject.org/f01/rdoproject.org/f01e852df9384aec987b051f9dc35eda/ 2025-09-29 16:03:20.953692 | Event ID: 5e2aef00-9d4d-11f0-865a-f599bea11f4e 2025-09-29 16:03:20.957715 | 2025-09-29 16:03:20.957805 | LOOP [emit-job-header : Print node information] 2025-09-29 16:03:21.091434 | localhost | ok: 2025-09-29 16:03:21.091591 | localhost | # Node Information 2025-09-29 16:03:21.091618 | localhost | Inventory Hostname: controller 2025-09-29 16:03:21.091641 | localhost | Hostname: np0005460112 2025-09-29 16:03:21.091660 | localhost | Username: zuul 2025-09-29 16:03:21.091680 | localhost | Distro: CentOS 9 2025-09-29 16:03:21.091697 | localhost | Provider: vexxhost-nodepool-tripleo 2025-09-29 16:03:21.091714 | localhost | Region: RegionOne 2025-09-29 16:03:21.091752 | localhost | Label: cloud-centos-9-stream-tripleo 2025-09-29 16:03:21.091771 | localhost | Product Name: OpenStack Nova 2025-09-29 16:03:21.091787 | localhost | Interface IP: 38.129.56.189 2025-09-29 16:03:21.130397 | 2025-09-29 16:03:21.130516 | PLAY [all] 2025-09-29 16:03:21.143221 | 2025-09-29 16:03:21.143303 | TASK [Gather network facts] 2025-09-29 16:03:21.610059 | controller | ok 2025-09-29 16:03:21.639286 | 2025-09-29 16:03:21.639372 | TASK [include_role : start-zuul-console] 2025-09-29 16:03:21.657245 | controller | ok 2025-09-29 16:03:21.685896 | 2025-09-29 16:03:21.685978 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-29 16:03:22.135072 | controller | ok 2025-09-29 16:03:22.157600 | 2025-09-29 16:03:22.157720 | TASK [include_role : add-build-sshkey] 2025-09-29 16:03:22.184630 | controller | ok 2025-09-29 16:03:22.199398 | 2025-09-29 16:03:22.199514 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-29 16:03:22.439979 | controller -> localhost | ok 2025-09-29 16:03:22.447044 | 2025-09-29 16:03:22.447137 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-29 16:03:22.480459 | controller | ok 2025-09-29 16:03:22.498062 | controller | included: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-29 16:03:22.504634 | 2025-09-29 16:03:22.504712 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-29 16:03:23.103938 | controller -> localhost | Generating public/private rsa key pair. 2025-09-29 16:03:23.104146 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/work/f01e852df9384aec987b051f9dc35eda_id_rsa. 2025-09-29 16:03:23.104178 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/work/f01e852df9384aec987b051f9dc35eda_id_rsa.pub. 2025-09-29 16:03:23.104201 | controller -> localhost | The key fingerprint is: 2025-09-29 16:03:23.104221 | controller -> localhost | SHA256:F+jgUFcG7RmeET4cjrll8TexUDP7lVyqWQBWs3oCAqk zuul-build-sshkey 2025-09-29 16:03:23.104241 | controller -> localhost | The key's randomart image is: 2025-09-29 16:03:23.104260 | controller -> localhost | +---[RSA 3072]----+ 2025-09-29 16:03:23.104278 | controller -> localhost | | ... o+O+=.= .| 2025-09-29 16:03:23.104297 | controller -> localhost | | .o . X++ =.Bo| 2025-09-29 16:03:23.104316 | controller -> localhost | | .. o =oO=o Bo.| 2025-09-29 16:03:23.104335 | controller -> localhost | | E o + ==+ = o.| 2025-09-29 16:03:23.104353 | controller -> localhost | | . S + + .| 2025-09-29 16:03:23.104371 | controller -> localhost | | . o | 2025-09-29 16:03:23.104573 | controller -> localhost | | | 2025-09-29 16:03:23.104592 | controller -> localhost | | | 2025-09-29 16:03:23.104611 | controller -> localhost | | | 2025-09-29 16:03:23.104628 | controller -> localhost | +----[SHA256]-----+ 2025-09-29 16:03:23.104670 | controller -> localhost | ok: Runtime: 0:00:00.187299 2025-09-29 16:03:23.110621 | 2025-09-29 16:03:23.110699 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-29 16:03:23.146823 | controller | ok 2025-09-29 16:03:23.157471 | controller | included: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-29 16:03:23.167660 | 2025-09-29 16:03:23.167792 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-29 16:03:23.192041 | controller | skipping: Conditional result was False 2025-09-29 16:03:23.199157 | 2025-09-29 16:03:23.199272 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-29 16:03:23.696943 | controller | changed 2025-09-29 16:03:23.709414 | 2025-09-29 16:03:23.709592 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-29 16:03:23.993461 | controller | ok 2025-09-29 16:03:24.002010 | 2025-09-29 16:03:24.002147 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-29 16:03:24.896482 | controller | changed 2025-09-29 16:03:24.903441 | 2025-09-29 16:03:24.903611 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-29 16:03:25.710101 | controller | changed 2025-09-29 16:03:25.720604 | 2025-09-29 16:03:25.720702 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-29 16:03:25.744801 | controller | skipping: Conditional result was False 2025-09-29 16:03:25.751297 | 2025-09-29 16:03:25.751374 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-29 16:03:26.183207 | controller -> localhost | changed 2025-09-29 16:03:26.198741 | 2025-09-29 16:03:26.198876 | TASK [add-build-sshkey : Add back temp key] 2025-09-29 16:03:26.448462 | controller -> localhost | Identity added: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/work/f01e852df9384aec987b051f9dc35eda_id_rsa (zuul-build-sshkey) 2025-09-29 16:03:26.448995 | controller -> localhost | ok: Runtime: 0:00:00.012050 2025-09-29 16:03:26.461682 | 2025-09-29 16:03:26.461922 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-29 16:03:26.821071 | controller | ok 2025-09-29 16:03:26.832548 | 2025-09-29 16:03:26.832801 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-29 16:03:26.875936 | controller | skipping: Conditional result was False 2025-09-29 16:03:26.900286 | 2025-09-29 16:03:26.900455 | TASK [include_role : validate-host] 2025-09-29 16:03:26.930567 | controller | ok 2025-09-29 16:03:26.949714 | 2025-09-29 16:03:26.949853 | TASK [validate-host : Define zuul_info_dir fact] 2025-09-29 16:03:26.978908 | controller | ok 2025-09-29 16:03:26.987850 | 2025-09-29 16:03:26.987920 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-09-29 16:03:27.247324 | controller -> localhost | ok 2025-09-29 16:03:27.253671 | 2025-09-29 16:03:27.253796 | TASK [validate-host : Collect information about the host] 2025-09-29 16:03:27.982367 | controller | ok 2025-09-29 16:03:27.994219 | 2025-09-29 16:03:27.994337 | TASK [validate-host : Sanitize hostname] 2025-09-29 16:03:28.048140 | controller | ok 2025-09-29 16:03:28.055225 | 2025-09-29 16:03:28.055358 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-09-29 16:03:28.549170 | controller -> localhost | changed 2025-09-29 16:03:28.555058 | 2025-09-29 16:03:28.555139 | TASK [validate-host : Collect information about zuul worker] 2025-09-29 16:03:28.972608 | controller | ok 2025-09-29 16:03:28.978702 | 2025-09-29 16:03:28.978847 | TASK [validate-host : Write out all zuul information for each host] 2025-09-29 16:03:29.431597 | controller -> localhost | changed 2025-09-29 16:03:29.446518 | 2025-09-29 16:03:29.446630 | TASK [include_role : prepare-workspace-openshift] 2025-09-29 16:03:29.470608 | controller | skipping: Conditional result was False 2025-09-29 16:03:29.477546 | 2025-09-29 16:03:29.477665 | TASK [include_role : remove-zuul-sshkey] 2025-09-29 16:03:29.501971 | controller | skipping: Conditional result was False 2025-09-29 16:03:29.508757 | 2025-09-29 16:03:29.508884 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-29 16:03:29.753579 | controller | ok: "logs" 2025-09-29 16:03:29.753866 | controller | ok: All items complete 2025-09-29 16:03:29.753895 | 2025-09-29 16:03:29.986462 | controller | ok: "artifacts" 2025-09-29 16:03:30.196318 | controller | ok: "docs" 2025-09-29 16:03:30.240993 | 2025-09-29 16:03:30.241108 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-29 16:03:30.539266 | controller | changed: "logs" 2025-09-29 16:03:30.880778 | controller | changed: "artifacts" 2025-09-29 16:03:31.121081 | controller | changed: "docs" 2025-09-29 16:03:31.144408 | 2025-09-29 16:03:31.144501 | PLAY RECAP 2025-09-29 16:03:31.144540 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-09-29 16:03:31.144565 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-29 16:03:31.144582 | 2025-09-29 16:03:31.281856 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-09-29 16:03:31.283026 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-09-29 16:03:31.855985 | 2025-09-29 16:03:31.856114 | PLAY [localhost] 2025-09-29 16:03:31.872212 | 2025-09-29 16:03:31.872314 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-09-29 16:03:32.246166 | localhost | ok 2025-09-29 16:03:32.251205 | 2025-09-29 16:03:32.251285 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-09-29 16:03:33.042192 | localhost | changed 2025-09-29 16:03:33.070483 | 2025-09-29 16:03:33.070643 | PLAY [all] 2025-09-29 16:03:33.088409 | 2025-09-29 16:03:33.088527 | TASK [include_role : prepare-workspace] 2025-09-29 16:03:33.107794 | controller | ok 2025-09-29 16:03:33.122558 | 2025-09-29 16:03:33.122890 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-29 16:03:33.517773 | controller | ok 2025-09-29 16:03:33.525218 | 2025-09-29 16:03:33.525323 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-29 16:03:35.263336 | controller | Output suppressed because no_log was given 2025-09-29 16:03:35.283313 | 2025-09-29 16:03:35.283438 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-29 16:03:35.539953 | controller | changed: "logs" 2025-09-29 16:03:35.770050 | controller | changed: "artifacts" 2025-09-29 16:03:36.013080 | controller | changed: "docs" 2025-09-29 16:03:36.041014 | 2025-09-29 16:03:36.041192 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-29 16:03:36.303098 | controller | changed: "logs" 2025-09-29 16:03:36.303368 | controller | changed: All items complete 2025-09-29 16:03:36.303396 | 2025-09-29 16:03:36.549047 | controller | changed: "artifacts" 2025-09-29 16:03:36.781898 | controller | changed: "docs" 2025-09-29 16:03:36.819867 | 2025-09-29 16:03:36.820062 | TASK [Check if worker can sudo] 2025-09-29 16:03:37.381008 | controller | ok: Runtime: 0:00:00.048265 2025-09-29 16:03:37.386778 | 2025-09-29 16:03:37.386874 | TASK [configure-mirrors : Gather needed facts] 2025-09-29 16:03:37.452215 | controller | skipping: Conditional result was False 2025-09-29 16:03:37.458880 | 2025-09-29 16:03:37.458984 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-09-29 16:03:37.526693 | controller | ok 2025-09-29 16:03:37.545997 | controller | included: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-09-29 16:03:37.555195 | 2025-09-29 16:03:37.555294 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-09-29 16:03:37.909870 | controller | ok 2025-09-29 16:03:37.916442 | 2025-09-29 16:03:37.916529 | LOOP [configure-mirrors : Include OS-specific variables] 2025-09-29 16:03:38.021335 | controller | ok: "/var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-09-29 16:03:38.031356 | 2025-09-29 16:03:38.031496 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-09-29 16:03:38.969581 | controller | changed 2025-09-29 16:03:38.983886 | 2025-09-29 16:03:38.984091 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-09-29 16:03:39.042961 | controller | ok: "/var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-09-29 16:03:39.043286 | controller | ok: All items complete 2025-09-29 16:03:39.043327 | 2025-09-29 16:03:39.138992 | controller | included: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-09-29 16:03:39.148522 | 2025-09-29 16:03:39.148690 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-09-29 16:03:40.111045 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-09-29 16:03:41.008835 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-09-29 16:03:41.030566 | 2025-09-29 16:03:41.030787 | TASK [configure-mirrors : Disable deltrarpm] 2025-09-29 16:03:41.508912 | controller | changed: section and option added 2025-09-29 16:03:41.553517 | 2025-09-29 16:03:41.553911 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-09-29 16:03:42.508352 | controller | 29 files removed 2025-09-29 16:03:42.508779 | controller | ok: Item: dnf clean all Runtime: 0:00:00.591070 2025-09-29 16:03:42.508875 | controller | changed: All items complete 2025-09-29 16:03:42.508925 | 2025-09-29 16:03:54.514006 | 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-29 16:03:54.514117 | controller | DNF version: 4.14.0 2025-09-29 16:03:54.514142 | controller | cachedir: /var/cache/dnf 2025-09-29 16:03:54.514161 | controller | Making cache files for all metadata files. 2025-09-29 16:03:54.514178 | controller | baseos: has expired and will be refreshed. 2025-09-29 16:03:54.514195 | controller | appstream: has expired and will be refreshed. 2025-09-29 16:03:54.514211 | controller | crb: has expired and will be refreshed. 2025-09-29 16:03:54.514236 | controller | extras-common: has expired and will be refreshed. 2025-09-29 16:03:54.514252 | controller | repo: downloading from remote: baseos 2025-09-29 16:03:54.514268 | controller | CentOS Stream 9 - BaseOS 51 MB/s | 8.8 MB 00:00 2025-09-29 16:03:54.514393 | controller | baseos: using metadata from Mon 22 Sep 2025 10:29:43 AM EDT. 2025-09-29 16:03:54.514419 | controller | repo: downloading from remote: appstream 2025-09-29 16:03:54.514437 | controller | CentOS Stream 9 - AppStream 42 MB/s | 25 MB 00:00 2025-09-29 16:03:54.514454 | controller | appstream: using metadata from Mon 22 Sep 2025 10:33:24 AM EDT. 2025-09-29 16:03:54.514470 | controller | repo: downloading from remote: crb 2025-09-29 16:03:54.514486 | controller | CentOS Stream 9 - CRB 48 MB/s | 7.1 MB 00:00 2025-09-29 16:03:54.514502 | controller | crb: using metadata from Mon 22 Sep 2025 10:37:51 AM EDT. 2025-09-29 16:03:54.514517 | controller | repo: downloading from remote: extras-common 2025-09-29 16:03:54.514533 | controller | CentOS Stream 9 - Extras packages 1.3 MB/s | 20 kB 00:00 2025-09-29 16:03:54.514549 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-09-29 16:03:54.514564 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-09-29 16:03:54.514579 | controller | Completion plugin: Generating completion cache... 2025-09-29 16:03:54.514595 | controller | Metadata cache created. 2025-09-29 16:03:54.514621 | controller | ok: Item: dnf makecache -v Runtime: 0:00:11.763385 2025-09-29 16:03:54.533889 | 2025-09-29 16:03:54.533998 | PLAY RECAP 2025-09-29 16:03:54.534038 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-09-29 16:03:54.534063 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-29 16:03:54.534080 | 2025-09-29 16:03:54.649901 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-09-29 16:03:54.650960 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-29 16:03:55.247075 | 2025-09-29 16:03:55.247186 | PLAY [all] 2025-09-29 16:03:55.268816 | 2025-09-29 16:03:55.268929 | TASK [Install binary dependencies] 2025-09-29 16:03:55.308190 | controller | ok 2025-09-29 16:03:55.327510 | 2025-09-29 16:03:55.327615 | TASK [bindep : Include find tasks] 2025-09-29 16:03:55.356880 | controller | ok 2025-09-29 16:03:55.364408 | controller | included: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-29 16:03:55.370364 | 2025-09-29 16:03:55.370427 | TASK [bindep : Look for bindep.txt] 2025-09-29 16:03:55.830516 | controller | ok 2025-09-29 16:03:55.838003 | 2025-09-29 16:03:55.838104 | TASK [bindep : Define bindep_file fact] 2025-09-29 16:03:55.876954 | controller | ok 2025-09-29 16:03:55.882056 | 2025-09-29 16:03:55.882127 | TASK [bindep : Look for other-requirements.txt] 2025-09-29 16:03:55.905776 | controller | skipping: Conditional result was False 2025-09-29 16:03:55.911811 | 2025-09-29 16:03:55.911893 | TASK [bindep : Define bindep_file fact] 2025-09-29 16:03:55.936006 | controller | skipping: Conditional result was False 2025-09-29 16:03:55.942283 | 2025-09-29 16:03:55.942387 | TASK [bindep : Look for bindep fallback file] 2025-09-29 16:03:55.975940 | controller | skipping: Conditional result was False 2025-09-29 16:03:55.981622 | 2025-09-29 16:03:55.981747 | TASK [bindep : Define bindep_file fact] 2025-09-29 16:03:56.005469 | controller | skipping: Conditional result was False 2025-09-29 16:03:56.011441 | 2025-09-29 16:03:56.011530 | TASK [bindep : Include bindep tasks] 2025-09-29 16:03:56.041635 | controller | ok 2025-09-29 16:03:56.047941 | controller | included: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-09-29 16:03:56.055761 | 2025-09-29 16:03:56.055828 | TASK [bindep : Look for bindep command] 2025-09-29 16:03:56.089901 | controller | skipping: Conditional result was False 2025-09-29 16:03:56.096530 | 2025-09-29 16:03:56.096629 | TASK [bindep : Check for system bindep] 2025-09-29 16:03:56.629497 | controller | ok: Runtime: 0:00:00.004986 2025-09-29 16:03:56.642144 | 2025-09-29 16:03:56.642313 | TASK [bindep : Define bindep_command fact] 2025-09-29 16:03:56.679529 | controller | skipping: Conditional result was False 2025-09-29 16:03:56.692430 | 2025-09-29 16:03:56.692583 | TASK [bindep : Include install tasks] 2025-09-29 16:03:56.734607 | controller | ok 2025-09-29 16:03:56.746431 | controller | included: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-09-29 16:03:56.767886 | 2025-09-29 16:03:56.768115 | TASK [bindep : Create temp dir for bindep] 2025-09-29 16:03:57.174062 | controller | changed 2025-09-29 16:03:57.187545 | 2025-09-29 16:03:57.187762 | TASK [Ensure we have pip dependencies] 2025-09-29 16:03:57.214431 | controller | ok 2025-09-29 16:03:57.254174 | 2025-09-29 16:03:57.254523 | TASK [ensure-pip : Check if pip is installed] 2025-09-29 12:03:57.543202 | controller | /usr/bin/pip3 2025-09-29 12:03:57.569202 | controller | /usr/bin/python3: No module named wheel 2025-09-29 16:03:57.786339 | controller | ok: Runtime: 0:00:00.036556 2025-09-29 16:03:57.799060 | 2025-09-29 16:03:57.799223 | LOOP [ensure-pip : Install pip from packages] 2025-09-29 16:03:57.844357 | controller | ok: "/var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-09-29 16:03:57.864086 | controller | included: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-09-29 16:03:57.903788 | 2025-09-29 16:03:57.903928 | TASK [ensure-pip : Install Python 3 pip] 2025-09-29 16:04:02.061893 | controller | changed 2025-09-29 16:04:02.070109 | 2025-09-29 16:04:02.070214 | TASK [ensure-pip : Check for EPEL repository] 2025-09-29 16:04:02.116573 | controller | skipping: Conditional result was False 2025-09-29 16:04:02.125605 | 2025-09-29 16:04:02.125751 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-09-29 16:04:02.173052 | controller | skipping: Conditional result was False 2025-09-29 16:04:02.180295 | 2025-09-29 16:04:02.180423 | TASK [ensure-pip : Install Python 2 pip] 2025-09-29 16:04:02.215486 | controller | skipping: Conditional result was False 2025-09-29 16:04:02.222288 | 2025-09-29 16:04:02.222464 | TASK [ensure-pip : Ensure setuptools] 2025-09-29 16:04:02.236687 | controller | skipping: Conditional result was False 2025-09-29 16:04:02.243819 | 2025-09-29 16:04:02.243923 | TASK [ensure-pip : Check for ensurepip module] 2025-09-29 16:04:02.776251 | controller | skipping: Conditional result was False 2025-09-29 16:04:02.785562 | 2025-09-29 16:04:02.785697 | TASK [ensure-pip : Ensure python3-venv] 2025-09-29 16:04:02.811245 | controller | skipping: Conditional result was False 2025-09-29 16:04:02.827158 | 2025-09-29 16:04:02.827337 | TASK [ensure-pip : Install pip from source] 2025-09-29 16:04:02.846852 | controller | skipping: Conditional result was False 2025-09-29 16:04:02.860620 | 2025-09-29 16:04:02.860805 | TASK [ensure-pip : Probe for venv python full path] 2025-09-29 12:04:03.140433 | controller | /usr/bin/python3 2025-09-29 16:04:03.420323 | controller | ok: Runtime: 0:00:00.006997 2025-09-29 16:04:03.433128 | 2025-09-29 16:04:03.433319 | TASK [ensure-pip : Set host default] 2025-09-29 16:04:03.493256 | controller | ok 2025-09-29 16:04:03.504665 | 2025-09-29 16:04:03.504960 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-09-29 16:04:03.566625 | controller | ok 2025-09-29 16:04:03.588902 | 2025-09-29 16:04:03.589093 | TASK [bindep : Install bindep into temporary venv] 2025-09-29 16:04:09.066282 | controller | changed 2025-09-29 16:04:09.078779 | 2025-09-29 16:04:09.078923 | TASK [bindep : Define bindep_command] 2025-09-29 16:04:09.119379 | controller | ok 2025-09-29 16:04:09.132292 | 2025-09-29 16:04:09.132427 | LOOP [bindep : Include package tasks] 2025-09-29 16:04:09.207922 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-09-29 16:04:09.208133 | controller | ok: All items complete 2025-09-29 16:04:09.208172 | 2025-09-29 16:04:09.220787 | controller | included: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-09-29 16:04:09.236276 | 2025-09-29 16:04:09.236368 | TASK [bindep : Define bindep_run fact] 2025-09-29 16:04:09.267449 | controller | ok 2025-09-29 16:04:09.272321 | 2025-09-29 16:04:09.272382 | TASK [bindep : Get list of packages to install from bindep] 2025-09-29 12:04:10.636653 | controller | podman 2025-09-29 12:04:10.667808 | controller | python3-jmespath 2025-09-29 12:04:10.667971 | controller | python3-libvirt 2025-09-29 12:04:10.667982 | controller | python3-lxml 2025-09-29 12:04:10.667989 | controller | python3-netaddr 2025-09-29 16:04:10.803779 | controller | ok: Runtime: 0:00:01.156857 2025-09-29 16:04:10.817101 | 2025-09-29 16:04:10.817285 | TASK [bindep : Install distro packages from bindep] 2025-09-29 16:05:24.161254 | controller | changed 2025-09-29 16:05:24.170061 | 2025-09-29 16:05:24.170188 | TASK [bindep : Check that packages are installed] 2025-09-29 16:05:25.713929 | controller | ok: Runtime: 0:00:01.242587 2025-09-29 16:05:25.724782 | 2025-09-29 16:05:25.724921 | TASK [bindep : Fail if we cannot install all packages] 2025-09-29 16:05:25.751938 | controller | skipping: Conditional result was False 2025-09-29 16:05:25.766875 | 2025-09-29 16:05:25.767424 | TASK [Run test-setup role] 2025-09-29 16:05:25.786661 | controller | ok 2025-09-29 16:05:25.824184 | 2025-09-29 16:05:25.824348 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-29 16:05:26.135523 | controller | ok 2025-09-29 16:05:26.144938 | 2025-09-29 16:05:26.145078 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-29 16:05:26.689757 | controller | skipping: Conditional result was False 2025-09-29 16:05:26.728996 | 2025-09-29 16:05:26.729154 | TASK [bindep : Remove bindep temp dir] 2025-09-29 16:05:27.102209 | controller | ok 2025-09-29 16:05:27.118700 | 2025-09-29 16:05:27.118826 | PLAY RECAP 2025-09-29 16:05:27.118875 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-09-29 16:05:27.118897 | 2025-09-29 16:05:27.234067 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-29 16:05:27.235520 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-09-29 16:05:27.885903 | 2025-09-29 16:05:27.886030 | PLAY [all] 2025-09-29 16:05:27.906491 | 2025-09-29 16:05:27.906620 | TASK [Abort when test_command variable is undefined] 2025-09-29 16:05:27.942242 | controller | skipping: Conditional result was False 2025-09-29 16:05:27.947978 | 2025-09-29 16:05:27.948080 | TASK [Convert test_command to list] 2025-09-29 16:05:27.983178 | controller | skipping: Conditional result was False 2025-09-29 16:05:27.990122 | 2025-09-29 16:05:27.990234 | TASK [Use test_command list] 2025-09-29 16:05:28.040671 | controller | ok 2025-09-29 16:05:28.047478 | 2025-09-29 16:05:28.047576 | LOOP [Run test_command] 2025-09-29 16:05:28.485207 | controller | no check to run 2025-09-29 16:05:28.485449 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.008045 2025-09-29 16:05:28.535048 | 2025-09-29 16:05:28.535168 | PLAY RECAP 2025-09-29 16:05:28.535225 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-09-29 16:05:28.535256 | 2025-09-29 16:05:28.677546 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-09-29 16:05:28.678421 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-29 16:05:29.268021 | 2025-09-29 16:05:29.268150 | PLAY [all] 2025-09-29 16:05:29.290044 | 2025-09-29 16:05:29.290177 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-29 16:05:29.657931 | controller | changed: non-zero return code 2025-09-29 16:05:29.663370 | 2025-09-29 16:05:29.663464 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-29 16:05:29.677374 | controller | skipping: Conditional result was False 2025-09-29 16:05:29.683044 | 2025-09-29 16:05:29.683115 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-29 16:05:29.703179 | 2025-09-29 16:05:29.703341 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-29 16:05:29.723465 | 2025-09-29 16:05:29.723662 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-29 16:05:29.748027 | controller | skipping: Conditional result was False 2025-09-29 16:05:29.754279 | 2025-09-29 16:05:29.754365 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-29 16:05:29.783955 | 2025-09-29 16:05:29.784109 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-29 16:05:29.809445 | controller | skipping: Conditional result was False 2025-09-29 16:05:29.814819 | 2025-09-29 16:05:29.814921 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-29 16:05:29.839099 | controller | skipping: Conditional result was False 2025-09-29 16:05:29.847997 | 2025-09-29 16:05:29.848084 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-29 16:05:29.862669 | controller | skipping: Conditional result was False 2025-09-29 16:05:29.887791 | 2025-09-29 16:05:29.887875 | PLAY RECAP 2025-09-29 16:05:29.887917 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-29 16:05:29.887937 | 2025-09-29 16:05:29.990229 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-29 16:05:29.991094 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-29 16:05:30.599829 | 2025-09-29 16:05:30.599955 | PLAY [all] 2025-09-29 16:05:30.619657 | 2025-09-29 16:05:30.619795 | TASK [include_role : fetch-output] 2025-09-29 16:05:30.658966 | controller | ok 2025-09-29 16:05:30.675773 | 2025-09-29 16:05:30.675863 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-29 16:05:30.729916 | controller | skipping: Conditional result was False 2025-09-29 16:05:30.735824 | 2025-09-29 16:05:30.735895 | TASK [fetch-output : Set log path for single node] 2025-09-29 16:05:30.785014 | controller | ok 2025-09-29 16:05:30.790045 | 2025-09-29 16:05:30.790110 | LOOP [fetch-output : Ensure local output dirs] 2025-09-29 16:05:31.310637 | controller -> localhost | ok: "/var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/work/logs" 2025-09-29 16:05:31.598549 | controller -> localhost | changed: "/var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/work/artifacts" 2025-09-29 16:05:31.805546 | controller -> localhost | changed: "/var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/work/docs" 2025-09-29 16:05:31.821265 | 2025-09-29 16:05:31.821383 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-29 16:05:32.612046 | controller | changed: .d..t...... ./ 2025-09-29 16:05:32.612240 | controller | changed: All items complete 2025-09-29 16:05:32.612268 | 2025-09-29 16:05:33.143216 | controller | changed: .d..t...... ./ 2025-09-29 16:05:33.625159 | controller | changed: .d..t...... ./ 2025-09-29 16:05:33.639657 | 2025-09-29 16:05:33.639801 | TASK [include_role : fetch-output-openshift] 2025-09-29 16:05:33.655413 | controller | skipping: Conditional result was False 2025-09-29 16:05:33.661987 | 2025-09-29 16:05:33.662065 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-29 16:05:34.197326 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.009147 2025-09-29 16:05:34.458508 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.016480 2025-09-29 16:05:34.511287 | 2025-09-29 16:05:34.511385 | PLAY [all] 2025-09-29 16:05:34.528079 | 2025-09-29 16:05:34.528147 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-09-29 16:05:34.970454 | controller | changed 2025-09-29 16:05:34.996521 | 2025-09-29 16:05:34.996603 | PLAY RECAP 2025-09-29 16:05:34.996644 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-09-29 16:05:34.996665 | 2025-09-29 16:05:35.107133 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-09-29 16:05:35.108001 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-09-29 16:05:35.742188 | 2025-09-29 16:05:35.742317 | PLAY [localhost] 2025-09-29 16:05:35.763161 | 2025-09-29 16:05:35.763297 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-29 16:05:36.203306 | localhost | changed 2025-09-29 16:05:36.208164 | 2025-09-29 16:05:36.208249 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-29 16:05:36.237590 | localhost | ok 2025-09-29 16:05:36.247589 | 2025-09-29 16:05:36.247788 | TASK [add-fileserver : Create SSH private key tempfile] 2025-09-29 16:05:36.622747 | localhost | changed 2025-09-29 16:05:36.637073 | 2025-09-29 16:05:36.637205 | TASK [add-fileserver : Create SSH private key from secret] 2025-09-29 16:05:37.427334 | localhost | changed 2025-09-29 16:05:37.432468 | 2025-09-29 16:05:37.432535 | TASK [add-fileserver : Add fileserver ssh key] 2025-09-29 16:05:37.894581 | localhost | Identity added: /var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/work/tmp/ansible.rfbjrtgw (/var/lib/zuul/builds/f01e852df9384aec987b051f9dc35eda/work/tmp/ansible.rfbjrtgw) 2025-09-29 16:05:37.894782 | localhost | ok: Runtime: 0:00:00.010389 2025-09-29 16:05:37.899250 | 2025-09-29 16:05:37.899322 | TASK [add-fileserver : Remove SSH private key from disk] 2025-09-29 16:05:38.178605 | localhost | ok: Runtime: 0:00:00.010888 2025-09-29 16:05:38.189987 | 2025-09-29 16:05:38.190134 | TASK [add-fileserver : Add fileserver to inventory] 2025-09-29 16:05:38.251985 | localhost | changed 2025-09-29 16:05:38.256374 | 2025-09-29 16:05:38.256444 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-09-29 16:05:38.666231 | localhost | changed 2025-09-29 16:05:38.694512 | 2025-09-29 16:05:38.694616 | PLAY [localhost] 2025-09-29 16:05:38.713700 | 2025-09-29 16:05:38.713778 | TASK [Generate bulk log download script] 2025-09-29 16:05:38.731306 | localhost | ok 2025-09-29 16:05:38.742990 | 2025-09-29 16:05:38.743057 | TASK [local-log-download : Check API endpoint is defined] 2025-09-29 16:05:38.781371 | localhost | ok: All assertions passed 2025-09-29 16:05:38.786114 | 2025-09-29 16:05:38.786174 | TASK [local-log-download : Create download script] 2025-09-29 16:05:39.251072 | localhost -> localhost | changed 2025-09-29 16:05:39.261449 | 2025-09-29 16:05:39.261604 | TASK [Register quick-download link] 2025-09-29 16:05:39.298102 | localhost | ok 2025-09-29 16:05:39.369911 | 2025-09-29 16:05:39.370035 | PLAY [logserver.rdoproject.org] 2025-09-29 16:05:39.385151 | 2025-09-29 16:05:39.385259 | TASK [Set zuul-log-path fact] 2025-09-29 16:05:39.403902 | logserver.rdoproject.org | ok 2025-09-29 16:05:39.417782 | 2025-09-29 16:05:39.417900 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-29 16:05:39.446977 | logserver.rdoproject.org | ok 2025-09-29 16:05:39.454713 | 2025-09-29 16:05:39.454833 | TASK [upload-logs : Create log directories] 2025-09-29 16:05:40.172116 | logserver.rdoproject.org | changed 2025-09-29 16:05:40.179780 | 2025-09-29 16:05:40.179926 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-09-29 16:05:40.519355 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.007854 2025-09-29 16:05:40.530426 | 2025-09-29 16:05:40.530558 | TASK [upload-logs : Upload logs to log server] 2025-09-29 16:05:41.241827 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-09-29 16:05:41.248624 | 2025-09-29 16:05:41.248787 | LOOP [upload-logs : Compress console log and json output] 2025-09-29 16:05:41.319925 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-29 16:05:41.330813 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-29 16:05:41.345579 | 2025-09-29 16:05:41.345869 | LOOP [upload-logs : Upload compressed console log and json output] 2025-09-29 16:05:41.398375 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-29 16:05:41.398687 | 2025-09-29 16:05:41.402254 | logserver.rdoproject.org | skipping: Conditional result was False 2025-09-29 16:05:41.409009 | 2025-09-29 16:05:41.409151 | LOOP [upload-logs : Upload console log and json output]