2025-11-28 05:49:30.389500 | Job console starting... 2025-11-28 05:49:30.399797 | Updating repositories 2025-11-28 05:49:30.425066 | Preparing job workspace 2025-11-28 05:49:34.173558 | Running Ansible setup... 2025-11-28 05:49:37.949519 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-11-28 05:49:38.568972 | 2025-11-28 05:49:38.569088 | PLAY [localhost] 2025-11-28 05:49:38.577625 | 2025-11-28 05:49:38.577710 | TASK [Gathering Facts] 2025-11-28 05:49:39.549258 | localhost | ok 2025-11-28 05:49:39.578621 | 2025-11-28 05:49:39.579025 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-28 05:49:39.970189 | localhost -> localhost | changed 2025-11-28 05:49:39.975742 | 2025-11-28 05:49:39.975809 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-28 05:49:40.738582 | localhost -> localhost | changed 2025-11-28 05:49:40.746884 | 2025-11-28 05:49:40.746951 | TASK [Setup log path fact] 2025-11-28 05:49:40.764524 | localhost | ok 2025-11-28 05:49:40.775751 | 2025-11-28 05:49:40.775814 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-28 05:49:40.803011 | localhost | ok 2025-11-28 05:49:40.810302 | 2025-11-28 05:49:40.810364 | TASK [emit-job-header : Print job information] 2025-11-28 05:49:40.847754 | # Job Information 2025-11-28 05:49:40.847871 | Ansible Version: 2.15.12 2025-11-28 05:49:40.847896 | Job: cifmw-molecule-pcp_metrics 2025-11-28 05:49:40.847915 | Pipeline: github-check 2025-11-28 05:49:40.847932 | Executor: ze02.softwarefactory-project.io 2025-11-28 05:49:40.847949 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3522 2025-11-28 05:49:40.847967 | Log URL (when completed): https://logserver.rdoproject.org/a0c/rdoproject.org/a0c7a259d7394121934379c90324c9af/ 2025-11-28 05:49:40.847984 | Event ID: caf38440-cc1d-11f0-8a6c-6125946660a4 2025-11-28 05:49:40.851510 | 2025-11-28 05:49:40.851571 | LOOP [emit-job-header : Print node information] 2025-11-28 05:49:40.943192 | localhost | ok: 2025-11-28 05:49:40.943361 | localhost | # Node Information 2025-11-28 05:49:40.943388 | localhost | Inventory Hostname: controller 2025-11-28 05:49:40.943409 | localhost | Hostname: np0005538469 2025-11-28 05:49:40.943428 | localhost | Username: zuul 2025-11-28 05:49:40.943448 | localhost | Distro: CentOS 9 2025-11-28 05:49:40.943466 | localhost | Provider: vexxhost-nodepool-tripleo 2025-11-28 05:49:40.943483 | localhost | Region: RegionOne 2025-11-28 05:49:40.943499 | localhost | Label: cloud-centos-9-stream-tripleo 2025-11-28 05:49:40.943515 | localhost | Product Name: OpenStack Nova 2025-11-28 05:49:40.943532 | localhost | Interface IP: 38.102.83.111 2025-11-28 05:49:40.968871 | 2025-11-28 05:49:40.968955 | PLAY [all] 2025-11-28 05:49:40.975265 | 2025-11-28 05:49:40.975325 | TASK [Gather network facts] 2025-11-28 05:49:41.501659 | controller | ok 2025-11-28 05:49:41.524268 | 2025-11-28 05:49:41.524327 | TASK [include_role : start-zuul-console] 2025-11-28 05:49:41.545278 | controller | ok 2025-11-28 05:49:41.559532 | 2025-11-28 05:49:41.559602 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-28 05:49:42.008701 | controller | ok 2025-11-28 05:49:42.017290 | 2025-11-28 05:49:42.017348 | TASK [include_role : add-build-sshkey] 2025-11-28 05:49:42.045719 | controller | ok 2025-11-28 05:49:42.059467 | 2025-11-28 05:49:42.059531 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-28 05:49:42.305817 | controller -> localhost | ok 2025-11-28 05:49:42.311275 | 2025-11-28 05:49:42.311335 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-28 05:49:42.339769 | controller | ok 2025-11-28 05:49:42.353115 | controller | included: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-28 05:49:42.359882 | 2025-11-28 05:49:42.359940 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-28 05:49:43.148181 | controller -> localhost | Generating public/private rsa key pair. 2025-11-28 05:49:43.148542 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/work/a0c7a259d7394121934379c90324c9af_id_rsa. 2025-11-28 05:49:43.148608 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/work/a0c7a259d7394121934379c90324c9af_id_rsa.pub. 2025-11-28 05:49:43.148656 | controller -> localhost | The key fingerprint is: 2025-11-28 05:49:43.148737 | controller -> localhost | SHA256:VoW1bQeb8SsnDV+s91Zh6ek2Fvc3QycWSfbKgda1GJM zuul-build-sshkey 2025-11-28 05:49:43.148781 | controller -> localhost | The key's randomart image is: 2025-11-28 05:49:43.148820 | controller -> localhost | +---[RSA 3072]----+ 2025-11-28 05:49:43.148858 | controller -> localhost | | ooo* .| 2025-11-28 05:49:43.148897 | controller -> localhost | | .. E+@o| 2025-11-28 05:49:43.148936 | controller -> localhost | | . +oX=*| 2025-11-28 05:49:43.148974 | controller -> localhost | | . . o**=| 2025-11-28 05:49:43.149012 | controller -> localhost | | S o*X=| 2025-11-28 05:49:43.149048 | controller -> localhost | | . .*oB| 2025-11-28 05:49:43.149084 | controller -> localhost | | B=| 2025-11-28 05:49:43.149121 | controller -> localhost | | o.=| 2025-11-28 05:49:43.149156 | controller -> localhost | | | 2025-11-28 05:49:43.149192 | controller -> localhost | +----[SHA256]-----+ 2025-11-28 05:49:43.149285 | controller -> localhost | ok: Runtime: 0:00:00.385805 2025-11-28 05:49:43.161198 | 2025-11-28 05:49:43.161326 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-28 05:49:43.197440 | controller | ok 2025-11-28 05:49:43.217701 | controller | included: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-28 05:49:43.231991 | 2025-11-28 05:49:43.232075 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-28 05:49:43.258456 | controller | skipping: Conditional result was False 2025-11-28 05:49:43.266162 | 2025-11-28 05:49:43.266247 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-28 05:49:43.796192 | controller | changed 2025-11-28 05:49:43.806630 | 2025-11-28 05:49:43.806804 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-28 05:49:44.108876 | controller | ok 2025-11-28 05:49:44.119390 | 2025-11-28 05:49:44.119518 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-28 05:49:45.135369 | controller | changed 2025-11-28 05:49:45.145971 | 2025-11-28 05:49:45.146100 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-28 05:49:46.162426 | controller | changed 2025-11-28 05:49:46.173175 | 2025-11-28 05:49:46.173310 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-28 05:49:46.199690 | controller | skipping: Conditional result was False 2025-11-28 05:49:46.210919 | 2025-11-28 05:49:46.211049 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-28 05:49:46.595207 | controller -> localhost | changed 2025-11-28 05:49:46.616593 | 2025-11-28 05:49:46.616758 | TASK [add-build-sshkey : Add back temp key] 2025-11-28 05:49:46.899370 | controller -> localhost | Identity added: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/work/a0c7a259d7394121934379c90324c9af_id_rsa (zuul-build-sshkey) 2025-11-28 05:49:46.899553 | controller -> localhost | ok: Runtime: 0:00:00.013840 2025-11-28 05:49:46.904976 | 2025-11-28 05:49:46.905035 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-28 05:49:47.340192 | controller | ok 2025-11-28 05:49:47.350297 | 2025-11-28 05:49:47.350427 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-28 05:49:47.386754 | controller | skipping: Conditional result was False 2025-11-28 05:49:47.403576 | 2025-11-28 05:49:47.403789 | TASK [include_role : validate-host] 2025-11-28 05:49:47.441968 | controller | ok 2025-11-28 05:49:47.483919 | 2025-11-28 05:49:47.484054 | TASK [validate-host : Define zuul_info_dir fact] 2025-11-28 05:49:47.528829 | controller | ok 2025-11-28 05:49:47.548945 | 2025-11-28 05:49:47.549083 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-11-28 05:49:47.810691 | controller -> localhost | ok 2025-11-28 05:49:47.816317 | 2025-11-28 05:49:47.816381 | TASK [validate-host : Collect information about the host] 2025-11-28 05:49:49.547659 | controller | ok 2025-11-28 05:49:49.571078 | 2025-11-28 05:49:49.571285 | TASK [validate-host : Sanitize hostname] 2025-11-28 05:49:49.635715 | controller | ok 2025-11-28 05:49:49.643331 | 2025-11-28 05:49:49.643430 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-11-28 05:49:50.118026 | controller -> localhost | changed 2025-11-28 05:49:50.123815 | 2025-11-28 05:49:50.123881 | TASK [validate-host : Collect information about zuul worker] 2025-11-28 05:49:50.578738 | controller | ok 2025-11-28 05:49:50.589182 | 2025-11-28 05:49:50.589316 | TASK [validate-host : Write out all zuul information for each host] 2025-11-28 05:49:51.107313 | controller -> localhost | changed 2025-11-28 05:49:51.117086 | 2025-11-28 05:49:51.117159 | TASK [include_role : prepare-workspace-openshift] 2025-11-28 05:49:51.141566 | controller | skipping: Conditional result was False 2025-11-28 05:49:51.146771 | 2025-11-28 05:49:51.146834 | TASK [include_role : remove-zuul-sshkey] 2025-11-28 05:49:51.171175 | controller | skipping: Conditional result was False 2025-11-28 05:49:51.187120 | 2025-11-28 05:49:51.187328 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-28 05:49:51.520511 | controller | ok: "logs" 2025-11-28 05:49:51.521043 | controller | ok: All items complete 2025-11-28 05:49:51.521104 | 2025-11-28 05:49:51.746184 | controller | ok: "artifacts" 2025-11-28 05:49:51.955829 | controller | ok: "docs" 2025-11-28 05:49:51.973528 | 2025-11-28 05:49:51.973740 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-28 05:49:52.296982 | controller | changed: "logs" 2025-11-28 05:49:52.555631 | controller | changed: "artifacts" 2025-11-28 05:49:52.775603 | controller | changed: "docs" 2025-11-28 05:49:52.823470 | 2025-11-28 05:49:52.823539 | PLAY RECAP 2025-11-28 05:49:52.823589 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-11-28 05:49:52.823623 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-28 05:49:52.823647 | 2025-11-28 05:49:52.923128 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-11-28 05:49:52.923964 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-11-28 05:49:53.505735 | 2025-11-28 05:49:53.505849 | PLAY [localhost] 2025-11-28 05:49:53.521633 | 2025-11-28 05:49:53.521747 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-11-28 05:49:53.957164 | localhost | ok 2025-11-28 05:49:53.967831 | 2025-11-28 05:49:53.967987 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-11-28 05:49:54.654223 | localhost | changed 2025-11-28 05:49:54.696635 | 2025-11-28 05:49:54.696727 | PLAY [all] 2025-11-28 05:49:54.717390 | 2025-11-28 05:49:54.717470 | TASK [include_role : prepare-workspace] 2025-11-28 05:49:54.739378 | controller | ok 2025-11-28 05:49:54.759980 | 2025-11-28 05:49:54.760104 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-28 05:49:55.229013 | controller | ok 2025-11-28 05:49:55.237835 | 2025-11-28 05:49:55.237918 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-28 05:49:57.184058 | controller | Output suppressed because no_log was given 2025-11-28 05:49:57.202016 | 2025-11-28 05:49:57.202105 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-28 05:49:57.521850 | controller | changed: "logs" 2025-11-28 05:49:57.787168 | controller | changed: "artifacts" 2025-11-28 05:49:58.019658 | controller | changed: "docs" 2025-11-28 05:49:58.040927 | 2025-11-28 05:49:58.041121 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-28 05:49:58.373223 | controller | changed: "logs" 2025-11-28 05:49:58.373603 | controller | changed: All items complete 2025-11-28 05:49:58.373689 | 2025-11-28 05:49:58.592733 | controller | changed: "artifacts" 2025-11-28 05:49:58.840601 | controller | changed: "docs" 2025-11-28 05:49:58.872432 | 2025-11-28 05:49:58.872623 | TASK [Check if worker can sudo] 2025-11-28 05:49:59.924488 | controller | ok: Runtime: 0:00:00.062423 2025-11-28 05:49:59.936433 | 2025-11-28 05:49:59.936563 | TASK [configure-mirrors : Gather needed facts] 2025-11-28 05:50:00.014311 | controller | skipping: Conditional result was False 2025-11-28 05:50:00.028125 | 2025-11-28 05:50:00.028314 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-11-28 05:50:00.130858 | controller | ok 2025-11-28 05:50:00.155764 | controller | included: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-11-28 05:50:00.192144 | 2025-11-28 05:50:00.192289 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-11-28 05:50:00.502625 | controller | ok 2025-11-28 05:50:00.514584 | 2025-11-28 05:50:00.514749 | LOOP [configure-mirrors : Include OS-specific variables] 2025-11-28 05:50:00.598702 | controller | ok: "/var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-11-28 05:50:00.616849 | 2025-11-28 05:50:00.617019 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-11-28 05:50:01.662100 | controller | changed 2025-11-28 05:50:01.673865 | 2025-11-28 05:50:01.674002 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-11-28 05:50:01.765849 | controller | ok: "/var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-11-28 05:50:01.766339 | controller | ok: All items complete 2025-11-28 05:50:01.766414 | 2025-11-28 05:50:01.850719 | controller | included: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-11-28 05:50:01.858078 | 2025-11-28 05:50:01.858149 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-11-28 05:50:02.987010 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-11-28 05:50:04.077375 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-11-28 05:50:04.097756 | 2025-11-28 05:50:04.097888 | TASK [configure-mirrors : Disable deltrarpm] 2025-11-28 05:50:04.636346 | controller | changed: section and option added 2025-11-28 05:50:04.678273 | 2025-11-28 05:50:04.678365 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-11-28 05:50:05.401166 | controller | 29 files removed 2025-11-28 05:50:05.401540 | controller | ok: Item: dnf clean all Runtime: 0:00:00.328304 2025-11-28 05:50:05.401625 | controller | changed: All items complete 2025-11-28 05:50:05.401701 | 2025-11-28 05:50:15.654427 | controller | Loaded plugins: builddep, changelog, config-manager, copr, debug, debuginfo-install, download, generate_completion_cache, groups-manager, needs-restarting, playground, repoclosure, repodiff, repograph, repomanage, reposync, system-upgrade 2025-11-28 05:50:15.654720 | controller | DNF version: 4.14.0 2025-11-28 05:50:15.654791 | controller | cachedir: /var/cache/dnf 2025-11-28 05:50:15.654838 | controller | Making cache files for all metadata files. 2025-11-28 05:50:15.654881 | controller | baseos: has expired and will be refreshed. 2025-11-28 05:50:15.654922 | controller | appstream: has expired and will be refreshed. 2025-11-28 05:50:15.654960 | controller | crb: has expired and will be refreshed. 2025-11-28 05:50:15.655010 | controller | extras-common: has expired and will be refreshed. 2025-11-28 05:50:15.655048 | controller | repo: downloading from remote: baseos 2025-11-28 05:50:15.655085 | controller | CentOS Stream 9 - BaseOS 70 MB/s | 8.8 MB 00:00 2025-11-28 05:50:15.655122 | controller | baseos: using metadata from Mon 24 Nov 2025 12:32:03 PM EST. 2025-11-28 05:50:15.655160 | controller | repo: downloading from remote: appstream 2025-11-28 05:50:15.655197 | controller | CentOS Stream 9 - AppStream 84 MB/s | 25 MB 00:00 2025-11-28 05:50:15.655234 | controller | appstream: using metadata from Mon 24 Nov 2025 12:35:27 PM EST. 2025-11-28 05:50:15.655270 | controller | repo: downloading from remote: crb 2025-11-28 05:50:15.655306 | controller | CentOS Stream 9 - CRB 79 MB/s | 7.3 MB 00:00 2025-11-28 05:50:15.655343 | controller | crb: using metadata from Mon 24 Nov 2025 12:39:46 PM EST. 2025-11-28 05:50:15.655379 | controller | repo: downloading from remote: extras-common 2025-11-28 05:50:15.655415 | controller | CentOS Stream 9 - Extras packages 1.5 MB/s | 20 kB 00:00 2025-11-28 05:50:15.655451 | controller | extras-common: using metadata from Thu 30 Oct 2025 09:20:08 AM EDT. 2025-11-28 05:50:15.655487 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-11-28 05:50:15.655524 | controller | Completion plugin: Generating completion cache... 2025-11-28 05:50:15.655561 | controller | Metadata cache created. 2025-11-28 05:50:15.655614 | controller | ok: Item: dnf makecache -v Runtime: 0:00:09.937223 2025-11-28 05:50:15.687282 | 2025-11-28 05:50:15.687389 | PLAY RECAP 2025-11-28 05:50:15.687474 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-11-28 05:50:15.687534 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-28 05:50:15.687577 | 2025-11-28 05:50:15.804600 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-11-28 05:50:15.805392 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-28 05:50:16.327240 | 2025-11-28 05:50:16.327342 | PLAY [all] 2025-11-28 05:50:16.347390 | 2025-11-28 05:50:16.347464 | TASK [Install binary dependencies] 2025-11-28 05:50:16.422416 | controller | ok 2025-11-28 05:50:16.450627 | 2025-11-28 05:50:16.450754 | TASK [bindep : Include find tasks] 2025-11-28 05:50:16.492106 | controller | ok 2025-11-28 05:50:16.502045 | controller | included: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-28 05:50:16.510061 | 2025-11-28 05:50:16.510144 | TASK [bindep : Look for bindep.txt] 2025-11-28 05:50:16.959742 | controller | ok 2025-11-28 05:50:16.968503 | 2025-11-28 05:50:16.968595 | TASK [bindep : Define bindep_file fact] 2025-11-28 05:50:17.010440 | controller | ok 2025-11-28 05:50:17.017175 | 2025-11-28 05:50:17.017259 | TASK [bindep : Look for other-requirements.txt] 2025-11-28 05:50:17.042085 | controller | skipping: Conditional result was False 2025-11-28 05:50:17.049456 | 2025-11-28 05:50:17.049545 | TASK [bindep : Define bindep_file fact] 2025-11-28 05:50:17.084504 | controller | skipping: Conditional result was False 2025-11-28 05:50:17.091996 | 2025-11-28 05:50:17.092082 | TASK [bindep : Look for bindep fallback file] 2025-11-28 05:50:17.127697 | controller | skipping: Conditional result was False 2025-11-28 05:50:17.135023 | 2025-11-28 05:50:17.135115 | TASK [bindep : Define bindep_file fact] 2025-11-28 05:50:17.171030 | controller | skipping: Conditional result was False 2025-11-28 05:50:17.179247 | 2025-11-28 05:50:17.179332 | TASK [bindep : Include bindep tasks] 2025-11-28 05:50:17.212574 | controller | ok 2025-11-28 05:50:17.221346 | controller | included: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-11-28 05:50:17.231651 | 2025-11-28 05:50:17.231756 | TASK [bindep : Look for bindep command] 2025-11-28 05:50:17.256743 | controller | skipping: Conditional result was False 2025-11-28 05:50:17.264857 | 2025-11-28 05:50:17.264939 | TASK [bindep : Check for system bindep] 2025-11-28 05:50:17.804099 | controller | ok: Runtime: 0:00:00.009064 2025-11-28 05:50:17.816591 | 2025-11-28 05:50:17.816802 | TASK [bindep : Define bindep_command fact] 2025-11-28 05:50:17.853761 | controller | skipping: Conditional result was False 2025-11-28 05:50:17.866792 | 2025-11-28 05:50:17.866941 | TASK [bindep : Include install tasks] 2025-11-28 05:50:17.915231 | controller | ok 2025-11-28 05:50:17.927638 | controller | included: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-11-28 05:50:17.939996 | 2025-11-28 05:50:17.940082 | TASK [bindep : Create temp dir for bindep] 2025-11-28 05:50:18.364009 | controller | changed 2025-11-28 05:50:18.375370 | 2025-11-28 05:50:18.375494 | TASK [Ensure we have pip dependencies] 2025-11-28 05:50:18.404090 | controller | ok 2025-11-28 05:50:18.444314 | 2025-11-28 05:50:18.444401 | TASK [ensure-pip : Check if pip is installed] 2025-11-28 00:50:18.757575 | controller | /usr/bin/pip3 2025-11-28 00:50:18.801000 | controller | /usr/bin/python3: No module named wheel 2025-11-28 05:50:18.978981 | controller | ok: Runtime: 0:00:00.057369 2025-11-28 05:50:18.991406 | 2025-11-28 05:50:18.991543 | LOOP [ensure-pip : Install pip from packages] 2025-11-28 05:50:19.031407 | controller | ok: "/var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-11-28 05:50:19.049409 | controller | included: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-11-28 05:50:19.068522 | 2025-11-28 05:50:19.068604 | TASK [ensure-pip : Install Python 3 pip] 2025-11-28 05:50:20.966914 | controller | changed 2025-11-28 05:50:20.981476 | 2025-11-28 05:50:20.981610 | TASK [ensure-pip : Check for EPEL repository] 2025-11-28 05:50:21.029339 | controller | skipping: Conditional result was False 2025-11-28 05:50:21.041597 | 2025-11-28 05:50:21.041768 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-11-28 05:50:21.088867 | controller | skipping: Conditional result was False 2025-11-28 05:50:21.101409 | 2025-11-28 05:50:21.101542 | TASK [ensure-pip : Install Python 2 pip] 2025-11-28 05:50:21.148464 | controller | skipping: Conditional result was False 2025-11-28 05:50:21.161138 | 2025-11-28 05:50:21.162065 | TASK [ensure-pip : Ensure setuptools] 2025-11-28 05:50:21.190148 | controller | skipping: Conditional result was False 2025-11-28 05:50:21.203857 | 2025-11-28 05:50:21.203994 | TASK [ensure-pip : Check for ensurepip module] 2025-11-28 05:50:21.748372 | controller | skipping: Conditional result was False 2025-11-28 05:50:21.760612 | 2025-11-28 05:50:21.760782 | TASK [ensure-pip : Ensure python3-venv] 2025-11-28 05:50:21.798699 | controller | skipping: Conditional result was False 2025-11-28 05:50:21.817010 | 2025-11-28 05:50:21.817188 | TASK [ensure-pip : Install pip from source] 2025-11-28 05:50:21.843503 | controller | skipping: Conditional result was False 2025-11-28 05:50:21.856755 | 2025-11-28 05:50:21.856861 | TASK [ensure-pip : Probe for venv python full path] 2025-11-28 00:50:22.166746 | controller | /usr/bin/python3 2025-11-28 05:50:22.401351 | controller | ok: Runtime: 0:00:00.004195 2025-11-28 05:50:22.412771 | 2025-11-28 05:50:22.412902 | TASK [ensure-pip : Set host default] 2025-11-28 05:50:22.490338 | controller | ok 2025-11-28 05:50:22.501066 | 2025-11-28 05:50:22.501196 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-11-28 05:50:22.570868 | controller | ok 2025-11-28 05:50:22.591728 | 2025-11-28 05:50:22.591861 | TASK [bindep : Install bindep into temporary venv] 2025-11-28 05:50:27.193024 | controller | changed 2025-11-28 05:50:27.205302 | 2025-11-28 05:50:27.205442 | TASK [bindep : Define bindep_command] 2025-11-28 05:50:27.244787 | controller | ok 2025-11-28 05:50:27.256388 | 2025-11-28 05:50:27.256522 | LOOP [bindep : Include package tasks] 2025-11-28 05:50:27.316925 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-11-28 05:50:27.317248 | controller | ok: All items complete 2025-11-28 05:50:27.317303 | 2025-11-28 05:50:27.342235 | controller | included: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-11-28 05:50:27.365644 | 2025-11-28 05:50:27.365806 | TASK [bindep : Define bindep_run fact] 2025-11-28 05:50:27.399989 | controller | ok 2025-11-28 05:50:27.406860 | 2025-11-28 05:50:27.406945 | TASK [bindep : Get list of packages to install from bindep] 2025-11-28 00:50:28.911824 | controller | podman 2025-11-28 00:50:28.960522 | controller | python3-jmespath 2025-11-28 00:50:28.960562 | controller | python3-libvirt 2025-11-28 00:50:28.960577 | controller | python3-lxml 2025-11-28 00:50:28.960595 | controller | python3-netaddr 2025-11-28 05:50:29.451991 | controller | ok: Runtime: 0:00:01.278155 2025-11-28 05:50:29.463997 | 2025-11-28 05:50:29.464134 | TASK [bindep : Install distro packages from bindep] 2025-11-28 05:51:28.321310 | controller | changed 2025-11-28 05:51:28.335080 | 2025-11-28 05:51:28.335218 | TASK [bindep : Check that packages are installed] 2025-11-28 05:51:30.411946 | controller | ok: Runtime: 0:00:01.303982 2025-11-28 05:51:30.423990 | 2025-11-28 05:51:30.424124 | TASK [bindep : Fail if we cannot install all packages] 2025-11-28 05:51:30.460864 | controller | skipping: Conditional result was False 2025-11-28 05:51:30.483836 | 2025-11-28 05:51:30.483971 | TASK [Run test-setup role] 2025-11-28 05:51:30.511556 | controller | ok 2025-11-28 05:51:30.540033 | 2025-11-28 05:51:30.540146 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-28 05:51:30.821260 | controller | ok 2025-11-28 05:51:30.834474 | 2025-11-28 05:51:30.834608 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-28 05:51:31.382198 | controller | skipping: Conditional result was False 2025-11-28 05:51:31.427846 | 2025-11-28 05:51:31.428029 | TASK [bindep : Remove bindep temp dir] 2025-11-28 05:51:31.822590 | controller | ok 2025-11-28 05:51:31.844419 | 2025-11-28 05:51:31.844551 | PLAY RECAP 2025-11-28 05:51:31.844633 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-11-28 05:51:31.844716 | 2025-11-28 05:51:31.967911 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-28 05:51:31.968779 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-11-28 05:51:32.507215 | 2025-11-28 05:51:32.507318 | PLAY [all] 2025-11-28 05:51:32.525947 | 2025-11-28 05:51:32.526015 | TASK [Abort when test_command variable is undefined] 2025-11-28 05:51:32.560541 | controller | skipping: Conditional result was False 2025-11-28 05:51:32.566430 | 2025-11-28 05:51:32.566515 | TASK [Convert test_command to list] 2025-11-28 05:51:32.620922 | controller | skipping: Conditional result was False 2025-11-28 05:51:32.627593 | 2025-11-28 05:51:32.627655 | TASK [Use test_command list] 2025-11-28 05:51:32.686685 | controller | ok 2025-11-28 05:51:32.691836 | 2025-11-28 05:51:32.691895 | LOOP [Run test_command] 2025-11-28 05:51:33.115839 | controller | no check to run 2025-11-28 05:51:33.116187 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.006836 2025-11-28 05:51:33.142742 | 2025-11-28 05:51:33.142852 | PLAY RECAP 2025-11-28 05:51:33.142894 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-11-28 05:51:33.142913 | 2025-11-28 05:51:33.227572 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-11-28 05:51:33.228410 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-28 05:51:33.779279 | 2025-11-28 05:51:33.779386 | PLAY [all] 2025-11-28 05:51:33.799081 | 2025-11-28 05:51:33.799166 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-28 05:51:34.170814 | controller | changed: non-zero return code 2025-11-28 05:51:34.182303 | 2025-11-28 05:51:34.182460 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-28 05:51:34.209626 | controller | skipping: Conditional result was False 2025-11-28 05:51:34.221074 | 2025-11-28 05:51:34.221217 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-28 05:51:34.259906 | 2025-11-28 05:51:34.260141 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-28 05:51:34.299046 | 2025-11-28 05:51:34.299280 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-28 05:51:34.325888 | controller | skipping: Conditional result was False 2025-11-28 05:51:34.338100 | 2025-11-28 05:51:34.338244 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-28 05:51:34.375968 | 2025-11-28 05:51:34.376271 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-28 05:51:34.403977 | controller | skipping: Conditional result was False 2025-11-28 05:51:34.417056 | 2025-11-28 05:51:34.417197 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-28 05:51:34.444369 | controller | skipping: Conditional result was False 2025-11-28 05:51:34.456194 | 2025-11-28 05:51:34.456331 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-28 05:51:34.472912 | controller | skipping: Conditional result was False 2025-11-28 05:51:34.515452 | 2025-11-28 05:51:34.515521 | PLAY RECAP 2025-11-28 05:51:34.515576 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-28 05:51:34.515604 | 2025-11-28 05:51:34.607243 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-28 05:51:34.609032 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-11-28 05:51:35.188633 | 2025-11-28 05:51:35.188759 | PLAY [all] 2025-11-28 05:51:35.207320 | 2025-11-28 05:51:35.207393 | TASK [include_role : fetch-output] 2025-11-28 05:51:35.245978 | controller | ok 2025-11-28 05:51:35.262115 | 2025-11-28 05:51:35.262190 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-28 05:51:35.326810 | controller | skipping: Conditional result was False 2025-11-28 05:51:35.339163 | 2025-11-28 05:51:35.339307 | TASK [fetch-output : Set log path for single node] 2025-11-28 05:51:35.386891 | controller | ok 2025-11-28 05:51:35.397972 | 2025-11-28 05:51:35.398109 | LOOP [fetch-output : Ensure local output dirs] 2025-11-28 05:51:35.828858 | controller -> localhost | ok: "/var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/work/logs" 2025-11-28 05:51:36.097081 | controller -> localhost | changed: "/var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/work/artifacts" 2025-11-28 05:51:36.405147 | controller -> localhost | changed: "/var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/work/docs" 2025-11-28 05:51:36.428528 | 2025-11-28 05:51:36.428745 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-28 05:51:37.188492 | controller | changed: .d..t...... ./ 2025-11-28 05:51:37.188855 | controller | changed: All items complete 2025-11-28 05:51:37.188916 | 2025-11-28 05:51:37.739695 | controller | changed: .d..t...... ./ 2025-11-28 05:51:38.305288 | controller | changed: .d..t...... ./ 2025-11-28 05:51:38.332897 | 2025-11-28 05:51:38.333164 | TASK [include_role : fetch-output-openshift] 2025-11-28 05:51:38.359520 | controller | skipping: Conditional result was False 2025-11-28 05:51:38.372382 | 2025-11-28 05:51:38.372523 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-28 05:51:38.851653 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.012103 2025-11-28 05:51:39.119594 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.012402 2025-11-28 05:51:39.155331 | 2025-11-28 05:51:39.155441 | PLAY [all] 2025-11-28 05:51:39.169558 | 2025-11-28 05:51:39.169621 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-11-28 05:51:39.627976 | controller | changed 2025-11-28 05:51:39.671707 | 2025-11-28 05:51:39.671808 | PLAY RECAP 2025-11-28 05:51:39.671864 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-11-28 05:51:39.671892 | 2025-11-28 05:51:39.765181 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-11-28 05:51:39.766765 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-11-28 05:51:40.399204 | 2025-11-28 05:51:40.399328 | PLAY [localhost] 2025-11-28 05:51:40.416983 | 2025-11-28 05:51:40.417059 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-28 05:51:40.826548 | localhost | changed 2025-11-28 05:51:40.836287 | 2025-11-28 05:51:40.836442 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-28 05:51:40.871654 | localhost | ok 2025-11-28 05:51:40.888775 | 2025-11-28 05:51:40.888931 | TASK [add-fileserver : Create SSH private key tempfile] 2025-11-28 05:51:41.261604 | localhost | changed 2025-11-28 05:51:41.273551 | 2025-11-28 05:51:41.273771 | TASK [add-fileserver : Create SSH private key from secret] 2025-11-28 05:51:41.943901 | localhost | changed 2025-11-28 05:51:41.948880 | 2025-11-28 05:51:41.948941 | TASK [add-fileserver : Add fileserver ssh key] 2025-11-28 05:51:42.353503 | localhost | Identity added: /var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/work/tmp/ansible.8g3jc9tt (/var/lib/zuul/builds/a0c7a259d7394121934379c90324c9af/work/tmp/ansible.8g3jc9tt) 2025-11-28 05:51:42.353702 | localhost | ok: Runtime: 0:00:00.007400 2025-11-28 05:51:42.358125 | 2025-11-28 05:51:42.358189 | TASK [add-fileserver : Remove SSH private key from disk] 2025-11-28 05:51:42.639132 | localhost | ok: Runtime: 0:00:00.004248 2025-11-28 05:51:42.657546 | 2025-11-28 05:51:42.657733 | TASK [add-fileserver : Add fileserver to inventory] 2025-11-28 05:51:42.725170 | localhost | changed 2025-11-28 05:51:42.734984 | 2025-11-28 05:51:42.735129 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-11-28 05:51:43.106936 | localhost | changed 2025-11-28 05:51:43.147785 | 2025-11-28 05:51:43.147912 | PLAY [localhost] 2025-11-28 05:51:43.164098 | 2025-11-28 05:51:43.164179 | TASK [Generate bulk log download script] 2025-11-28 05:51:43.185567 | localhost | ok 2025-11-28 05:51:43.201373 | 2025-11-28 05:51:43.201463 | TASK [local-log-download : Check API endpoint is defined] 2025-11-28 05:51:43.231449 | localhost | ok: All assertions passed 2025-11-28 05:51:43.237630 | 2025-11-28 05:51:43.237737 | TASK [local-log-download : Create download script] 2025-11-28 05:51:43.701215 | localhost -> localhost | changed 2025-11-28 05:51:43.720564 | 2025-11-28 05:51:43.720729 | TASK [Register quick-download link] 2025-11-28 05:51:43.756097 | localhost | ok 2025-11-28 05:51:43.816215 | 2025-11-28 05:51:43.816336 | PLAY [logserver.rdoproject.org] 2025-11-28 05:51:43.828852 | 2025-11-28 05:51:43.828933 | TASK [Set zuul-log-path fact] 2025-11-28 05:51:43.847258 | logserver.rdoproject.org | ok 2025-11-28 05:51:43.859250 | 2025-11-28 05:51:43.859334 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-28 05:51:43.899333 | logserver.rdoproject.org | ok 2025-11-28 05:51:43.911314 | 2025-11-28 05:51:43.911470 | TASK [upload-logs : Create log directories] 2025-11-28 05:51:44.893019 | logserver.rdoproject.org | changed 2025-11-28 05:51:44.899630 | 2025-11-28 05:51:44.899828 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-11-28 05:51:45.223074 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.008194 2025-11-28 05:51:45.232598 | 2025-11-28 05:51:45.232771 | TASK [upload-logs : Upload logs to log server] 2025-11-28 05:51:45.936007 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-11-28 05:51:45.942157 | 2025-11-28 05:51:45.942308 | LOOP [upload-logs : Compress console log and json output] 2025-11-28 05:51:45.989706 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-28 05:51:45.997716 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-28 05:51:46.008813 | 2025-11-28 05:51:46.008970 | LOOP [upload-logs : Upload compressed console log and json output] 2025-11-28 05:51:46.051154 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-28 05:51:46.051457 | 2025-11-28 05:51:46.054809 | logserver.rdoproject.org | skipping: Conditional result was False 2025-11-28 05:51:46.062984 | 2025-11-28 05:51:46.063128 | LOOP [upload-logs : Upload console log and json output]