2025-10-03 12:45:06.903416 | Job console starting... 2025-10-03 12:45:06.915685 | Updating repositories 2025-10-03 12:45:06.944120 | Preparing job workspace 2025-10-03 12:45:10.597923 | Running Ansible setup... 2025-10-03 12:45:14.273316 | PRE-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-03 12:45:14.930719 | 2025-10-03 12:45:14.930846 | PLAY [localhost] 2025-10-03 12:45:14.942490 | 2025-10-03 12:45:14.942576 | TASK [Gathering Facts] 2025-10-03 12:45:15.919877 | localhost | ok 2025-10-03 12:45:15.936517 | 2025-10-03 12:45:15.936663 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-03 12:45:16.324363 | localhost -> localhost | changed 2025-10-03 12:45:16.331177 | 2025-10-03 12:45:16.331281 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-03 12:45:17.236661 | localhost -> localhost | changed 2025-10-03 12:45:17.246099 | 2025-10-03 12:45:17.246451 | TASK [Setup log path fact] 2025-10-03 12:45:17.264948 | localhost | ok 2025-10-03 12:45:17.279943 | 2025-10-03 12:45:17.280049 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-03 12:45:17.308708 | localhost | ok 2025-10-03 12:45:17.316859 | 2025-10-03 12:45:17.316965 | TASK [emit-job-header : Print job information] 2025-10-03 12:45:17.354860 | # Job Information 2025-10-03 12:45:17.355003 | Ansible Version: 2.15.12 2025-10-03 12:45:17.355030 | Job: cifmw-molecule-cifmw_helpers 2025-10-03 12:45:17.355063 | Pipeline: github-check 2025-10-03 12:45:17.355084 | Executor: ze03.softwarefactory-project.io 2025-10-03 12:45:17.355102 | Triggered by: https://github.com/openstack-k8s-operators/ci-framework/pull/3366 2025-10-03 12:45:17.355121 | Log URL (when completed): https://logserver.rdoproject.org/24d/rdoproject.org/24d984782e614f5585297c552439e1f5/ 2025-10-03 12:45:17.355140 | Event ID: 8a294f00-a056-11f0-8eee-1e8238c96249 2025-10-03 12:45:17.359731 | 2025-10-03 12:45:17.359808 | LOOP [emit-job-header : Print node information] 2025-10-03 12:45:17.474252 | localhost | ok: 2025-10-03 12:45:17.474680 | localhost | # Node Information 2025-10-03 12:45:17.474790 | localhost | Inventory Hostname: controller 2025-10-03 12:45:17.474851 | localhost | Hostname: np0005468866 2025-10-03 12:45:17.474894 | localhost | Username: zuul 2025-10-03 12:45:17.474936 | localhost | Distro: CentOS 9 2025-10-03 12:45:17.474973 | localhost | Provider: vexxhost-nodepool-tripleo 2025-10-03 12:45:17.475010 | localhost | Region: RegionOne 2025-10-03 12:45:17.475046 | localhost | Label: cloud-centos-9-stream-tripleo 2025-10-03 12:45:17.475082 | localhost | Product Name: OpenStack Nova 2025-10-03 12:45:17.475117 | localhost | Interface IP: 38.102.83.234 2025-10-03 12:45:17.518802 | 2025-10-03 12:45:17.518890 | PLAY [all] 2025-10-03 12:45:17.525940 | 2025-10-03 12:45:17.526026 | TASK [Gather network facts] 2025-10-03 12:45:17.976366 | controller | ok 2025-10-03 12:45:17.993224 | 2025-10-03 12:45:17.993341 | TASK [include_role : start-zuul-console] 2025-10-03 12:45:18.012183 | controller | ok 2025-10-03 12:45:18.029244 | 2025-10-03 12:45:18.029370 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-03 12:45:18.394680 | controller | ok 2025-10-03 12:45:18.415462 | 2025-10-03 12:45:18.415631 | TASK [include_role : add-build-sshkey] 2025-10-03 12:45:18.451369 | controller | ok 2025-10-03 12:45:18.477786 | 2025-10-03 12:45:18.477928 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-03 12:45:18.739868 | controller -> localhost | ok 2025-10-03 12:45:18.746330 | 2025-10-03 12:45:18.746431 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-03 12:45:18.765412 | controller | ok 2025-10-03 12:45:18.780142 | controller | included: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-03 12:45:18.786979 | 2025-10-03 12:45:18.787088 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-03 12:45:19.366625 | controller -> localhost | Generating public/private rsa key pair. 2025-10-03 12:45:19.366852 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/work/24d984782e614f5585297c552439e1f5_id_rsa. 2025-10-03 12:45:19.366885 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/work/24d984782e614f5585297c552439e1f5_id_rsa.pub. 2025-10-03 12:45:19.366908 | controller -> localhost | The key fingerprint is: 2025-10-03 12:45:19.366929 | controller -> localhost | SHA256:gk5MEHyhpGY4KbN0QJtk9pOHju3OPzlklQwvSzGJx6s zuul-build-sshkey 2025-10-03 12:45:19.366948 | controller -> localhost | The key's randomart image is: 2025-10-03 12:45:19.366967 | controller -> localhost | +---[RSA 3072]----+ 2025-10-03 12:45:19.366985 | controller -> localhost | |.B+.+.. | 2025-10-03 12:45:19.367004 | controller -> localhost | |=+*++B | 2025-10-03 12:45:19.367022 | controller -> localhost | |B*.Bo.B . | 2025-10-03 12:45:19.367040 | controller -> localhost | |=+=oo= = | 2025-10-03 12:45:19.367057 | controller -> localhost | |.. o* = S | 2025-10-03 12:45:19.367075 | controller -> localhost | | .E + . | 2025-10-03 12:45:19.367093 | controller -> localhost | | .+ . | 2025-10-03 12:45:19.367113 | controller -> localhost | | o + | 2025-10-03 12:45:19.367131 | controller -> localhost | | o..o | 2025-10-03 12:45:19.367148 | controller -> localhost | +----[SHA256]-----+ 2025-10-03 12:45:19.367189 | controller -> localhost | ok: Runtime: 0:00:00.165822 2025-10-03 12:45:19.372683 | 2025-10-03 12:45:19.372767 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-03 12:45:19.391218 | controller | ok 2025-10-03 12:45:19.400978 | controller | included: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-03 12:45:19.410850 | 2025-10-03 12:45:19.410935 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-03 12:45:19.434955 | controller | skipping: Conditional result was False 2025-10-03 12:45:19.440718 | 2025-10-03 12:45:19.440812 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-03 12:45:19.915180 | controller | changed 2025-10-03 12:45:19.925550 | 2025-10-03 12:45:19.925696 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-03 12:45:20.215379 | controller | ok 2025-10-03 12:45:20.221341 | 2025-10-03 12:45:20.221441 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-03 12:45:21.148032 | controller | changed 2025-10-03 12:45:21.153799 | 2025-10-03 12:45:21.153886 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-03 12:45:21.997279 | controller | changed 2025-10-03 12:45:22.002817 | 2025-10-03 12:45:22.002908 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-03 12:45:22.030349 | controller | skipping: Conditional result was False 2025-10-03 12:45:22.037075 | 2025-10-03 12:45:22.037171 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-03 12:45:22.423061 | controller -> localhost | changed 2025-10-03 12:45:22.436225 | 2025-10-03 12:45:22.436399 | TASK [add-build-sshkey : Add back temp key] 2025-10-03 12:45:22.705354 | controller -> localhost | Identity added: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/work/24d984782e614f5585297c552439e1f5_id_rsa (zuul-build-sshkey) 2025-10-03 12:45:22.705565 | controller -> localhost | ok: Runtime: 0:00:00.011130 2025-10-03 12:45:22.713312 | 2025-10-03 12:45:22.713517 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-03 12:45:23.113708 | controller | ok 2025-10-03 12:45:23.119548 | 2025-10-03 12:45:23.119638 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-03 12:45:23.154112 | controller | skipping: Conditional result was False 2025-10-03 12:45:23.167721 | 2025-10-03 12:45:23.167821 | TASK [include_role : validate-host] 2025-10-03 12:45:23.187919 | controller | ok 2025-10-03 12:45:23.208051 | 2025-10-03 12:45:23.208129 | TASK [validate-host : Define zuul_info_dir fact] 2025-10-03 12:45:23.236832 | controller | ok 2025-10-03 12:45:23.241669 | 2025-10-03 12:45:23.241731 | TASK [validate-host : Ensure Zuul Ansible directory exists] 2025-10-03 12:45:23.489433 | controller -> localhost | ok 2025-10-03 12:45:23.495730 | 2025-10-03 12:45:23.495813 | TASK [validate-host : Collect information about the host] 2025-10-03 12:45:24.301047 | controller | ok 2025-10-03 12:45:24.312947 | 2025-10-03 12:45:24.313051 | TASK [validate-host : Sanitize hostname] 2025-10-03 12:45:24.363430 | controller | ok 2025-10-03 12:45:24.368365 | 2025-10-03 12:45:24.368429 | TASK [validate-host : Write out all ansible variables/facts known for each host] 2025-10-03 12:45:24.861936 | controller -> localhost | changed 2025-10-03 12:45:24.867563 | 2025-10-03 12:45:24.867630 | TASK [validate-host : Collect information about zuul worker] 2025-10-03 12:45:25.328873 | controller | ok 2025-10-03 12:45:25.336505 | 2025-10-03 12:45:25.336647 | TASK [validate-host : Write out all zuul information for each host] 2025-10-03 12:45:25.830557 | controller -> localhost | changed 2025-10-03 12:45:25.860777 | 2025-10-03 12:45:25.860929 | TASK [include_role : prepare-workspace-openshift] 2025-10-03 12:45:25.905587 | controller | skipping: Conditional result was False 2025-10-03 12:45:25.913373 | 2025-10-03 12:45:25.913539 | TASK [include_role : remove-zuul-sshkey] 2025-10-03 12:45:25.949545 | controller | skipping: Conditional result was False 2025-10-03 12:45:25.957895 | 2025-10-03 12:45:25.958008 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-03 12:45:26.271849 | controller | ok: "logs" 2025-10-03 12:45:26.272061 | controller | ok: All items complete 2025-10-03 12:45:26.272091 | 2025-10-03 12:45:26.490955 | controller | ok: "artifacts" 2025-10-03 12:45:26.712793 | controller | ok: "docs" 2025-10-03 12:45:26.727999 | 2025-10-03 12:45:26.728139 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-03 12:45:27.038641 | controller | changed: "logs" 2025-10-03 12:45:27.267039 | controller | changed: "artifacts" 2025-10-03 12:45:27.472113 | controller | changed: "docs" 2025-10-03 12:45:27.506763 | 2025-10-03 12:45:27.506885 | PLAY RECAP 2025-10-03 12:45:27.506944 | controller | ok: 22 changed: 9 unreachable: 0 failed: 0 skipped: 5 rescued: 0 ignored: 0 2025-10-03 12:45:27.506994 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-03 12:45:27.507025 | 2025-10-03 12:45:27.634068 | PRE-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/pre.yaml@master] 2025-10-03 12:45:27.634871 | PRE-RUN START: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-03 12:45:28.203920 | 2025-10-03 12:45:28.204031 | PLAY [localhost] 2025-10-03 12:45:28.220829 | 2025-10-03 12:45:28.220924 | TASK [configure-ssh-config-fips : Ensure ssh config directory] 2025-10-03 12:45:28.716545 | localhost | ok 2025-10-03 12:45:28.728650 | 2025-10-03 12:45:28.728894 | TASK [configure-ssh-config-fips : Setup ssh config] 2025-10-03 12:45:29.457407 | localhost | changed 2025-10-03 12:45:29.488267 | 2025-10-03 12:45:29.488366 | PLAY [all] 2025-10-03 12:45:29.513751 | 2025-10-03 12:45:29.513971 | TASK [include_role : prepare-workspace] 2025-10-03 12:45:29.534726 | controller | ok 2025-10-03 12:45:29.549044 | 2025-10-03 12:45:29.549148 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-03 12:45:29.937275 | controller | ok 2025-10-03 12:45:29.944214 | 2025-10-03 12:45:29.944303 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-03 12:45:31.560361 | controller | Output suppressed because no_log was given 2025-10-03 12:45:31.571624 | 2025-10-03 12:45:31.571764 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-03 12:45:31.836408 | controller | changed: "logs" 2025-10-03 12:45:32.090155 | controller | changed: "artifacts" 2025-10-03 12:45:32.293178 | controller | changed: "docs" 2025-10-03 12:45:32.310916 | 2025-10-03 12:45:32.311048 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-03 12:45:32.556109 | controller | changed: "logs" 2025-10-03 12:45:32.556324 | controller | changed: All items complete 2025-10-03 12:45:32.556351 | 2025-10-03 12:45:32.796078 | controller | changed: "artifacts" 2025-10-03 12:45:33.052771 | controller | changed: "docs" 2025-10-03 12:45:33.068568 | 2025-10-03 12:45:33.068703 | TASK [Check if worker can sudo] 2025-10-03 12:45:33.600533 | controller | ok: Runtime: 0:00:00.047722 2025-10-03 12:45:33.610403 | 2025-10-03 12:45:33.610609 | TASK [configure-mirrors : Gather needed facts] 2025-10-03 12:45:33.687853 | controller | skipping: Conditional result was False 2025-10-03 12:45:33.697004 | 2025-10-03 12:45:33.697105 | TASK [configure-mirrors : Set up infrastructure mirrors] 2025-10-03 12:45:33.760062 | controller | ok 2025-10-03 12:45:33.768028 | controller | included: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror.yaml 2025-10-03 12:45:33.773604 | 2025-10-03 12:45:33.773709 | TASK [configure-mirrors : Remove .pydistutils.cfg configuration in homedir] 2025-10-03 12:45:34.162786 | controller | ok 2025-10-03 12:45:34.171180 | 2025-10-03 12:45:34.171296 | LOOP [configure-mirrors : Include OS-specific variables] 2025-10-03 12:45:34.229494 | controller | ok: "/var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/vars/CentOS-9.yaml" 2025-10-03 12:45:34.246694 | 2025-10-03 12:45:34.246808 | TASK [configure-mirrors : Install /etc/pip.conf configuration] 2025-10-03 12:45:35.203678 | controller | changed 2025-10-03 12:45:35.215593 | 2025-10-03 12:45:35.215688 | LOOP [configure-mirrors : Setup distribution specific packaging mirrors] 2025-10-03 12:45:35.300590 | controller | ok: "/var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml" 2025-10-03 12:45:35.300782 | controller | ok: All items complete 2025-10-03 12:45:35.300819 | 2025-10-03 12:45:35.356617 | controller | included: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/configure-mirrors/tasks/mirror/CentOS-9.yaml 2025-10-03 12:45:35.363303 | 2025-10-03 12:45:35.363373 | LOOP [configure-mirrors : Install CentOS 9 repository files] 2025-10-03 12:45:36.380188 | controller | changed: "etc/yum.repos.d/centos.repo" 2025-10-03 12:45:37.250141 | controller | changed: "etc/yum.repos.d/centos-addons.repo" 2025-10-03 12:45:37.268365 | 2025-10-03 12:45:37.268627 | TASK [configure-mirrors : Disable deltrarpm] 2025-10-03 12:45:37.772688 | controller | changed: section and option added 2025-10-03 12:45:37.802558 | 2025-10-03 12:45:37.802750 | LOOP [configure-mirrors : Update yum/dnf cache] 2025-10-03 12:45:38.712655 | controller | 29 files removed 2025-10-03 12:45:38.712923 | controller | ok: Item: dnf clean all Runtime: 0:00:00.517551 2025-10-03 12:45:38.713211 | controller | changed: All items complete 2025-10-03 12:45:38.713249 | 2025-10-03 12:45:49.551204 | 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-03 12:45:49.551350 | controller | DNF version: 4.14.0 2025-10-03 12:45:49.551376 | controller | cachedir: /var/cache/dnf 2025-10-03 12:45:49.551396 | controller | Making cache files for all metadata files. 2025-10-03 12:45:49.551415 | controller | baseos: has expired and will be refreshed. 2025-10-03 12:45:49.551432 | controller | appstream: has expired and will be refreshed. 2025-10-03 12:45:49.551449 | controller | crb: has expired and will be refreshed. 2025-10-03 12:45:49.551475 | controller | extras-common: has expired and will be refreshed. 2025-10-03 12:45:49.551492 | controller | repo: downloading from remote: baseos 2025-10-03 12:45:49.551508 | controller | CentOS Stream 9 - BaseOS 70 MB/s | 8.8 MB 00:00 2025-10-03 12:45:49.551524 | controller | baseos: using metadata from Tue 30 Sep 2025 01:12:56 PM EDT. 2025-10-03 12:45:49.551540 | controller | repo: downloading from remote: appstream 2025-10-03 12:45:49.551556 | controller | CentOS Stream 9 - AppStream 97 MB/s | 25 MB 00:00 2025-10-03 12:45:49.551573 | controller | appstream: using metadata from Tue 30 Sep 2025 01:16:29 PM EDT. 2025-10-03 12:45:49.551589 | controller | repo: downloading from remote: crb 2025-10-03 12:45:49.551605 | controller | CentOS Stream 9 - CRB 80 MB/s | 7.1 MB 00:00 2025-10-03 12:45:49.551622 | controller | crb: using metadata from Tue 30 Sep 2025 01:20:54 PM EDT. 2025-10-03 12:45:49.551638 | controller | repo: downloading from remote: extras-common 2025-10-03 12:45:49.551654 | controller | CentOS Stream 9 - Extras packages 1.8 MB/s | 20 kB 00:00 2025-10-03 12:45:49.551671 | controller | extras-common: using metadata from Mon 15 Sep 2025 02:32:43 PM EDT. 2025-10-03 12:45:49.551687 | controller | User-Agent: constructed: 'libdnf (CentOS Stream 9; generic; Linux.x86_64)' 2025-10-03 12:45:49.551704 | controller | Completion plugin: Generating completion cache... 2025-10-03 12:45:49.551720 | controller | Metadata cache created. 2025-10-03 12:45:49.551772 | controller | ok: Item: dnf makecache -v Runtime: 0:00:10.565448 2025-10-03 12:45:49.563410 | 2025-10-03 12:45:49.563471 | PLAY RECAP 2025-10-03 12:45:49.563510 | controller | ok: 13 changed: 7 unreachable: 0 failed: 0 skipped: 1 rescued: 0 ignored: 0 2025-10-03 12:45:49.563535 | localhost | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-03 12:45:49.563553 | 2025-10-03 12:45:49.700094 | PRE-RUN END RESULT_NORMAL: [untrusted : review.rdoproject.org/rdo-jobs/playbooks/base/pre.yaml@master] 2025-10-03 12:45:49.700915 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-03 12:45:50.349426 | 2025-10-03 12:45:50.349558 | PLAY [all] 2025-10-03 12:45:50.385150 | 2025-10-03 12:45:50.385300 | TASK [Install binary dependencies] 2025-10-03 12:45:50.439847 | controller | ok 2025-10-03 12:45:50.470690 | 2025-10-03 12:45:50.470891 | TASK [bindep : Include find tasks] 2025-10-03 12:45:50.504341 | controller | ok 2025-10-03 12:45:50.516504 | controller | included: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-03 12:45:50.526812 | 2025-10-03 12:45:50.526953 | TASK [bindep : Look for bindep.txt] 2025-10-03 12:45:50.922746 | controller | ok 2025-10-03 12:45:50.931119 | 2025-10-03 12:45:50.931404 | TASK [bindep : Define bindep_file fact] 2025-10-03 12:45:50.961125 | controller | ok 2025-10-03 12:45:50.966968 | 2025-10-03 12:45:50.967091 | TASK [bindep : Look for other-requirements.txt] 2025-10-03 12:45:50.981587 | controller | skipping: Conditional result was False 2025-10-03 12:45:50.987720 | 2025-10-03 12:45:50.988107 | TASK [bindep : Define bindep_file fact] 2025-10-03 12:45:51.012202 | controller | skipping: Conditional result was False 2025-10-03 12:45:51.018800 | 2025-10-03 12:45:51.018927 | TASK [bindep : Look for bindep fallback file] 2025-10-03 12:45:51.043652 | controller | skipping: Conditional result was False 2025-10-03 12:45:51.050694 | 2025-10-03 12:45:51.050824 | TASK [bindep : Define bindep_file fact] 2025-10-03 12:45:51.075167 | controller | skipping: Conditional result was False 2025-10-03 12:45:51.082019 | 2025-10-03 12:45:51.082155 | TASK [bindep : Include bindep tasks] 2025-10-03 12:45:51.112768 | controller | ok 2025-10-03 12:45:51.119439 | controller | included: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find-bindep.yaml 2025-10-03 12:45:51.127786 | 2025-10-03 12:45:51.127901 | TASK [bindep : Look for bindep command] 2025-10-03 12:45:51.152149 | controller | skipping: Conditional result was False 2025-10-03 12:45:51.158856 | 2025-10-03 12:45:51.158954 | TASK [bindep : Check for system bindep] 2025-10-03 12:45:51.695481 | controller | ok: Runtime: 0:00:00.008781 2025-10-03 12:45:51.708864 | 2025-10-03 12:45:51.709032 | TASK [bindep : Define bindep_command fact] 2025-10-03 12:45:51.746332 | controller | skipping: Conditional result was False 2025-10-03 12:45:51.758869 | 2025-10-03 12:45:51.759005 | TASK [bindep : Include install tasks] 2025-10-03 12:45:51.801681 | controller | ok 2025-10-03 12:45:51.812689 | controller | included: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/install.yaml 2025-10-03 12:45:51.827436 | 2025-10-03 12:45:51.827558 | TASK [bindep : Create temp dir for bindep] 2025-10-03 12:45:52.281589 | controller | changed 2025-10-03 12:45:52.289444 | 2025-10-03 12:45:52.289642 | TASK [Ensure we have pip dependencies] 2025-10-03 12:45:52.314620 | controller | ok 2025-10-03 12:45:52.345142 | 2025-10-03 12:45:52.345262 | TASK [ensure-pip : Check if pip is installed] 2025-10-03 08:45:52.638579 | controller | /usr/bin/pip3 2025-10-03 08:45:52.671480 | controller | /usr/bin/python3: No module named wheel 2025-10-03 12:45:52.877977 | controller | ok: Runtime: 0:00:00.046513 2025-10-03 12:45:52.888618 | 2025-10-03 12:45:52.888834 | LOOP [ensure-pip : Install pip from packages] 2025-10-03 12:45:52.919185 | controller | ok: "/var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml" 2025-10-03 12:45:52.936392 | controller | included: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/ensure-pip/tasks/RedHat.yaml 2025-10-03 12:45:52.955471 | 2025-10-03 12:45:52.955655 | TASK [ensure-pip : Install Python 3 pip] 2025-10-03 12:45:55.399965 | controller | changed 2025-10-03 12:45:55.409218 | 2025-10-03 12:45:55.409373 | TASK [ensure-pip : Check for EPEL repository] 2025-10-03 12:45:55.459595 | controller | skipping: Conditional result was False 2025-10-03 12:45:55.467022 | 2025-10-03 12:45:55.467117 | TASK [ensure-pip : Fail with instructions when EPEL is not installed] 2025-10-03 12:45:55.509339 | controller | skipping: Conditional result was False 2025-10-03 12:45:55.530987 | 2025-10-03 12:45:55.531167 | TASK [ensure-pip : Install Python 2 pip] 2025-10-03 12:45:55.605521 | controller | skipping: Conditional result was False 2025-10-03 12:45:55.619164 | 2025-10-03 12:45:55.619456 | TASK [ensure-pip : Ensure setuptools] 2025-10-03 12:45:55.650343 | controller | skipping: Conditional result was False 2025-10-03 12:45:55.663279 | 2025-10-03 12:45:55.663432 | TASK [ensure-pip : Check for ensurepip module] 2025-10-03 12:45:56.203780 | controller | skipping: Conditional result was False 2025-10-03 12:45:56.211580 | 2025-10-03 12:45:56.211717 | TASK [ensure-pip : Ensure python3-venv] 2025-10-03 12:45:56.236879 | controller | skipping: Conditional result was False 2025-10-03 12:45:56.245770 | 2025-10-03 12:45:56.245918 | TASK [ensure-pip : Install pip from source] 2025-10-03 12:45:56.271999 | controller | skipping: Conditional result was False 2025-10-03 12:45:56.280615 | 2025-10-03 12:45:56.280794 | TASK [ensure-pip : Probe for venv python full path] 2025-10-03 08:45:56.552948 | controller | /usr/bin/python3 2025-10-03 12:45:56.820594 | controller | ok: Runtime: 0:00:00.008412 2025-10-03 12:45:56.831098 | 2025-10-03 12:45:56.831312 | TASK [ensure-pip : Set host default] 2025-10-03 12:45:56.957536 | controller | ok 2025-10-03 12:45:56.965492 | 2025-10-03 12:45:56.965577 | TASK [ensure-pip : Set ensure_pip_virtualenv_command] 2025-10-03 12:45:57.018920 | controller | ok 2025-10-03 12:45:57.041266 | 2025-10-03 12:45:57.041389 | TASK [bindep : Install bindep into temporary venv] 2025-10-03 12:46:01.762507 | controller | changed 2025-10-03 12:46:01.776839 | 2025-10-03 12:46:01.777170 | TASK [bindep : Define bindep_command] 2025-10-03 12:46:01.811561 | controller | ok 2025-10-03 12:46:01.819111 | 2025-10-03 12:46:01.819196 | LOOP [bindep : Include package tasks] 2025-10-03 12:46:01.887430 | controller | ok: "src/github.com/openstack-k8s-operators/ci-framework/bindep.txt" 2025-10-03 12:46:01.887611 | controller | ok: All items complete 2025-10-03 12:46:01.887646 | 2025-10-03 12:46:01.899932 | controller | included: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/untrusted/project_2/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/packages.yaml 2025-10-03 12:46:01.916997 | 2025-10-03 12:46:01.917081 | TASK [bindep : Define bindep_run fact] 2025-10-03 12:46:01.950842 | controller | ok 2025-10-03 12:46:01.958572 | 2025-10-03 12:46:01.958671 | TASK [bindep : Get list of packages to install from bindep] 2025-10-03 08:46:03.639750 | controller | podman 2025-10-03 08:46:03.693145 | controller | python3-jmespath 2025-10-03 08:46:03.693232 | controller | python3-libvirt 2025-10-03 08:46:03.693240 | controller | python3-lxml 2025-10-03 08:46:03.693303 | controller | python3-netaddr 2025-10-03 12:46:03.999705 | controller | ok: Runtime: 0:00:01.494794 2025-10-03 12:46:04.008813 | 2025-10-03 12:46:04.009240 | TASK [bindep : Install distro packages from bindep] 2025-10-03 12:47:09.506184 | controller | changed 2025-10-03 12:47:09.513301 | 2025-10-03 12:47:09.513367 | TASK [bindep : Check that packages are installed] 2025-10-03 12:47:11.106102 | controller | ok: Runtime: 0:00:01.125293 2025-10-03 12:47:11.112638 | 2025-10-03 12:47:11.112713 | TASK [bindep : Fail if we cannot install all packages] 2025-10-03 12:47:11.136765 | controller | skipping: Conditional result was False 2025-10-03 12:47:11.149915 | 2025-10-03 12:47:11.150460 | TASK [Run test-setup role] 2025-10-03 12:47:11.169418 | controller | ok 2025-10-03 12:47:11.187367 | 2025-10-03 12:47:11.187470 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-03 12:47:11.430568 | controller | ok 2025-10-03 12:47:11.435967 | 2025-10-03 12:47:11.436030 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-03 12:47:11.978103 | controller | skipping: Conditional result was False 2025-10-03 12:47:11.999467 | 2025-10-03 12:47:11.999595 | TASK [bindep : Remove bindep temp dir] 2025-10-03 12:47:12.387966 | controller | ok 2025-10-03 12:47:12.398419 | 2025-10-03 12:47:12.398476 | PLAY RECAP 2025-10-03 12:47:12.398518 | controller | ok: 22 changed: 6 unreachable: 0 failed: 0 skipped: 15 rescued: 0 ignored: 0 2025-10-03 12:47:12.398540 | 2025-10-03 12:47:12.508444 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-03 12:47:12.509321 | RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-03 12:47:13.187398 | 2025-10-03 12:47:13.187533 | PLAY [all] 2025-10-03 12:47:13.221770 | 2025-10-03 12:47:13.221910 | TASK [Abort when test_command variable is undefined] 2025-10-03 12:47:13.266770 | controller | skipping: Conditional result was False 2025-10-03 12:47:13.272908 | 2025-10-03 12:47:13.272995 | TASK [Convert test_command to list] 2025-10-03 12:47:13.321258 | controller | skipping: Conditional result was False 2025-10-03 12:47:13.329864 | 2025-10-03 12:47:13.329994 | TASK [Use test_command list] 2025-10-03 12:47:13.391908 | controller | ok 2025-10-03 12:47:13.398223 | 2025-10-03 12:47:13.398313 | LOOP [Run test_command] 2025-10-03 12:47:13.828046 | controller | no check to run 2025-10-03 12:47:13.828222 | controller | ok: Item: echo 'no check to run' Runtime: 0:00:00.006910 2025-10-03 12:47:13.853113 | 2025-10-03 12:47:13.853194 | PLAY RECAP 2025-10-03 12:47:13.853252 | controller | ok: 2 changed: 1 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-03 12:47:13.853275 | 2025-10-03 12:47:13.947219 | RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/run-test-command/run.yaml@master] 2025-10-03 12:47:13.948296 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-03 12:47:14.536811 | 2025-10-03 12:47:14.536936 | PLAY [all] 2025-10-03 12:47:14.562186 | 2025-10-03 12:47:14.562301 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-03 12:47:14.947994 | controller | changed: non-zero return code 2025-10-03 12:47:14.953456 | 2025-10-03 12:47:14.953532 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-03 12:47:14.972317 | controller | skipping: Conditional result was False 2025-10-03 12:47:14.980409 | 2025-10-03 12:47:14.980484 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-03 12:47:15.000887 | 2025-10-03 12:47:15.001033 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-03 12:47:15.022579 | 2025-10-03 12:47:15.022708 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-03 12:47:15.039354 | controller | skipping: Conditional result was False 2025-10-03 12:47:15.047459 | 2025-10-03 12:47:15.047573 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-03 12:47:15.072820 | 2025-10-03 12:47:15.072955 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-03 12:47:15.099899 | controller | skipping: Conditional result was False 2025-10-03 12:47:15.105893 | 2025-10-03 12:47:15.105973 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-03 12:47:15.130862 | controller | skipping: Conditional result was False 2025-10-03 12:47:15.138139 | 2025-10-03 12:47:15.138223 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-03 12:47:15.155485 | controller | skipping: Conditional result was False 2025-10-03 12:47:15.195773 | 2025-10-03 12:47:15.195886 | PLAY RECAP 2025-10-03 12:47:15.195952 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-03 12:47:15.195988 | 2025-10-03 12:47:15.333606 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-03 12:47:15.334405 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-03 12:47:15.933634 | 2025-10-03 12:47:15.933804 | PLAY [all] 2025-10-03 12:47:15.961709 | 2025-10-03 12:47:15.961908 | TASK [include_role : fetch-output] 2025-10-03 12:47:16.047750 | controller | ok 2025-10-03 12:47:16.073763 | 2025-10-03 12:47:16.073909 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-03 12:47:16.139709 | controller | skipping: Conditional result was False 2025-10-03 12:47:16.149622 | 2025-10-03 12:47:16.149746 | TASK [fetch-output : Set log path for single node] 2025-10-03 12:47:16.190649 | controller | ok 2025-10-03 12:47:16.197451 | 2025-10-03 12:47:16.197521 | LOOP [fetch-output : Ensure local output dirs] 2025-10-03 12:47:16.673993 | controller -> localhost | ok: "/var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/work/logs" 2025-10-03 12:47:16.904259 | controller -> localhost | changed: "/var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/work/artifacts" 2025-10-03 12:47:17.115043 | controller -> localhost | changed: "/var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/work/docs" 2025-10-03 12:47:17.126040 | 2025-10-03 12:47:17.126156 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-03 12:47:17.765180 | controller | changed: .d..t...... ./ 2025-10-03 12:47:17.765435 | controller | changed: All items complete 2025-10-03 12:47:17.765475 | 2025-10-03 12:47:18.223488 | controller | changed: .d..t...... ./ 2025-10-03 12:47:18.650643 | controller | changed: .d..t...... ./ 2025-10-03 12:47:18.675040 | 2025-10-03 12:47:18.675150 | TASK [include_role : fetch-output-openshift] 2025-10-03 12:47:18.700088 | controller | skipping: Conditional result was False 2025-10-03 12:47:18.706457 | 2025-10-03 12:47:18.706528 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-03 12:47:19.131019 | controller -> localhost | ok: Item: artifacts Runtime: 0:00:00.009492 2025-10-03 12:47:19.347310 | controller -> localhost | ok: Item: docs Runtime: 0:00:00.009415 2025-10-03 12:47:19.378762 | 2025-10-03 12:47:19.378924 | PLAY [all] 2025-10-03 12:47:19.393605 | 2025-10-03 12:47:19.393669 | TASK [remove-build-sshkey : Remove the build SSH key from all nodes] 2025-10-03 12:47:19.830517 | controller | changed 2025-10-03 12:47:19.890172 | 2025-10-03 12:47:19.890332 | PLAY RECAP 2025-10-03 12:47:19.890389 | controller | ok: 5 changed: 4 unreachable: 0 failed: 0 skipped: 2 rescued: 0 ignored: 0 2025-10-03 12:47:19.890416 | 2025-10-03 12:47:19.988543 | POST-RUN END RESULT_NORMAL: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-ssh.yaml@master] 2025-10-03 12:47:19.989421 | POST-RUN START: [trusted : review.rdoproject.org/config/playbooks/base-minimal/post-logs.yaml@master] 2025-10-03 12:47:20.638587 | 2025-10-03 12:47:20.638744 | PLAY [localhost] 2025-10-03 12:47:20.658460 | 2025-10-03 12:47:20.658596 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-03 12:47:21.043105 | localhost | changed 2025-10-03 12:47:21.050510 | 2025-10-03 12:47:21.050645 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-03 12:47:21.079655 | localhost | ok 2025-10-03 12:47:21.088026 | 2025-10-03 12:47:21.088131 | TASK [add-fileserver : Create SSH private key tempfile] 2025-10-03 12:47:21.517593 | localhost | changed 2025-10-03 12:47:21.523838 | 2025-10-03 12:47:21.523931 | TASK [add-fileserver : Create SSH private key from secret] 2025-10-03 12:47:22.183617 | localhost | changed 2025-10-03 12:47:22.197287 | 2025-10-03 12:47:22.197411 | TASK [add-fileserver : Add fileserver ssh key] 2025-10-03 12:47:22.630914 | localhost | Identity added: /var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/work/tmp/ansible.0ek0uzyv (/var/lib/zuul/builds/24d984782e614f5585297c552439e1f5/work/tmp/ansible.0ek0uzyv) 2025-10-03 12:47:22.631113 | localhost | ok: Runtime: 0:00:00.016055 2025-10-03 12:47:22.635784 | 2025-10-03 12:47:22.635856 | TASK [add-fileserver : Remove SSH private key from disk] 2025-10-03 12:47:22.930341 | localhost | ok: Runtime: 0:00:00.005648 2025-10-03 12:47:22.935089 | 2025-10-03 12:47:22.935150 | TASK [add-fileserver : Add fileserver to inventory] 2025-10-03 12:47:22.985628 | localhost | changed 2025-10-03 12:47:22.990705 | 2025-10-03 12:47:22.994063 | TASK [add-fileserver : Add fileserver server to known hosts] 2025-10-03 12:47:23.398020 | localhost | changed 2025-10-03 12:47:23.419270 | 2025-10-03 12:47:23.419590 | PLAY [localhost] 2025-10-03 12:47:23.432528 | 2025-10-03 12:47:23.432601 | TASK [Generate bulk log download script] 2025-10-03 12:47:23.450109 | localhost | ok 2025-10-03 12:47:23.462206 | 2025-10-03 12:47:23.462279 | TASK [local-log-download : Check API endpoint is defined] 2025-10-03 12:47:23.500648 | localhost | ok: All assertions passed 2025-10-03 12:47:23.505604 | 2025-10-03 12:47:23.505685 | TASK [local-log-download : Create download script] 2025-10-03 12:47:23.936483 | localhost -> localhost | changed 2025-10-03 12:47:23.949503 | 2025-10-03 12:47:23.949620 | TASK [Register quick-download link] 2025-10-03 12:47:23.971518 | localhost | ok 2025-10-03 12:47:24.025561 | 2025-10-03 12:47:24.025674 | PLAY [logserver.rdoproject.org] 2025-10-03 12:47:24.039073 | 2025-10-03 12:47:24.039192 | TASK [Set zuul-log-path fact] 2025-10-03 12:47:24.058136 | logserver.rdoproject.org | ok 2025-10-03 12:47:24.071126 | 2025-10-03 12:47:24.071254 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-03 12:47:24.100863 | logserver.rdoproject.org | ok 2025-10-03 12:47:24.108443 | 2025-10-03 12:47:24.108550 | TASK [upload-logs : Create log directories] 2025-10-03 12:47:25.130514 | logserver.rdoproject.org | changed 2025-10-03 12:47:25.134594 | 2025-10-03 12:47:25.134695 | TASK [upload-logs : Ensure logs are readable before uploading] 2025-10-03 12:47:25.445545 | logserver.rdoproject.org -> localhost | ok: Runtime: 0:00:00.004887 2025-10-03 12:47:25.450625 | 2025-10-03 12:47:25.450695 | TASK [upload-logs : Upload logs to log server] 2025-10-03 12:47:26.111496 | logserver.rdoproject.org | Output suppressed because no_log was given 2025-10-03 12:47:26.114377 | 2025-10-03 12:47:26.114438 | LOOP [upload-logs : Compress console log and json output] 2025-10-03 12:47:26.154582 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-03 12:47:26.163138 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-03 12:47:26.171381 | 2025-10-03 12:47:26.171475 | LOOP [upload-logs : Upload compressed console log and json output] 2025-10-03 12:47:26.209185 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-03 12:47:26.209515 | 2025-10-03 12:47:26.213235 | logserver.rdoproject.org | skipping: Conditional result was False 2025-10-03 12:47:26.219431 | 2025-10-03 12:47:26.219504 | LOOP [upload-logs : Upload console log and json output]