2025-10-18 00:23:42.039260 | Job console starting... 2025-10-18 00:23:42.047463 | Updating repositories 2025-10-18 00:23:42.166300 | Preparing job workspace 2025-10-18 00:23:46.317414 | Running Ansible setup... 2025-10-18 00:23:50.949449 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-18 00:23:51.618900 | 2025-10-18 00:23:51.619061 | PLAY [localhost] 2025-10-18 00:23:51.629280 | 2025-10-18 00:23:51.629427 | TASK [Gathering Facts] 2025-10-18 00:23:52.608229 | localhost | ok 2025-10-18 00:23:52.623016 | 2025-10-18 00:23:52.623153 | TASK [Setup log path fact] 2025-10-18 00:23:52.641384 | localhost | ok 2025-10-18 00:23:52.655070 | 2025-10-18 00:23:52.655189 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-18 00:23:52.683296 | localhost | ok 2025-10-18 00:23:52.691873 | 2025-10-18 00:23:52.691987 | TASK [emit-job-header : Print job information] 2025-10-18 00:23:52.732346 | # Job Information 2025-10-18 00:23:52.732552 | Ansible Version: 2.15.12 2025-10-18 00:23:52.732597 | Job: ansible-test-sanity-docker-milestone 2025-10-18 00:23:52.732629 | Pipeline: periodic 2025-10-18 00:23:52.732657 | Executor: ze03.softwarefactory-project.io 2025-10-18 00:23:52.732684 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-18 00:23:52.732717 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/407/ansible/40705bb6178648659304d2b9a6f157f3/ 2025-10-18 00:23:52.732776 | Event ID: 475bf33318134110a1dbccf99c35efa3 2025-10-18 00:23:52.738474 | 2025-10-18 00:23:52.738565 | LOOP [emit-job-header : Print node information] 2025-10-18 00:23:52.850902 | localhost | ok: 2025-10-18 00:23:52.851089 | localhost | # Node Information 2025-10-18 00:23:52.851120 | localhost | Inventory Hostname: controller 2025-10-18 00:23:52.851145 | localhost | Hostname: np0005493997 2025-10-18 00:23:52.851168 | localhost | Username: zuul 2025-10-18 00:23:52.851194 | localhost | Distro: Fedora 37 2025-10-18 00:23:52.851217 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-10-18 00:23:52.851239 | localhost | Region: ca-ymq-1 2025-10-18 00:23:52.851260 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-18 00:23:52.851281 | localhost | Product Name: OpenStack Nova 2025-10-18 00:23:52.851302 | localhost | Interface IP: 162.253.55.209 2025-10-18 00:23:52.873513 | 2025-10-18 00:23:52.873718 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-18 00:23:53.330265 | localhost -> localhost | changed 2025-10-18 00:23:53.336311 | 2025-10-18 00:23:53.336410 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-18 00:23:54.407905 | localhost -> localhost | changed 2025-10-18 00:23:54.437238 | 2025-10-18 00:23:54.437324 | PLAY [all:!appliance*] 2025-10-18 00:23:54.454331 | 2025-10-18 00:23:54.454452 | TASK [include_role : start-zuul-console] 2025-10-18 00:23:54.476496 | controller | ok 2025-10-18 00:23:54.489962 | 2025-10-18 00:23:54.490076 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-18 00:23:54.885117 | controller | ok 2025-10-18 00:23:54.901951 | 2025-10-18 00:23:54.902060 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-18 00:23:56.096916 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-18 00:23:56.103687 | 2025-10-18 00:23:56.103803 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-18 00:23:56.636233 | controller | skipping: Conditional result was False 2025-10-18 00:23:56.650250 | 2025-10-18 00:23:56.650436 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-18 00:23:56.677194 | controller | skipping: Conditional result was False 2025-10-18 00:23:56.691171 | 2025-10-18 00:23:56.691367 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-18 00:23:56.718177 | controller | skipping: Conditional result was False 2025-10-18 00:23:56.731948 | 2025-10-18 00:23:56.732140 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-18 00:23:56.759082 | controller | skipping: Conditional result was False 2025-10-18 00:23:56.768172 | 2025-10-18 00:23:56.768310 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-18 00:23:56.794389 | controller | skipping: Conditional result was False 2025-10-18 00:23:56.810812 | 2025-10-18 00:23:56.811016 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-18 00:23:56.837399 | controller | skipping: Conditional result was False 2025-10-18 00:23:56.854148 | 2025-10-18 00:23:56.854299 | TASK [Disable Fedora Modular] 2025-10-18 00:23:58.278870 | controller | changed 2025-10-18 00:23:58.287923 | 2025-10-18 00:23:58.288000 | TASK [Enable EPEL] 2025-10-18 00:23:58.304563 | controller | skipping: Conditional result was False 2025-10-18 00:23:58.318565 | 2025-10-18 00:23:58.318707 | TASK [Register the RHEL node] 2025-10-18 00:23:58.921508 | 2025-10-18 00:23:58.921684 | TASK [Show the subscription-manager status] 2025-10-18 00:23:59.463253 | controller | skipping: Conditional result was False 2025-10-18 00:23:59.472993 | 2025-10-18 00:23:59.473129 | TASK [Enable EPEL on RHEL] 2025-10-18 00:24:00.018605 | controller | skipping: Conditional result was False 2025-10-18 00:24:00.032312 | 2025-10-18 00:24:00.032518 | TASK [Install git and tox] 2025-10-18 00:25:34.048961 | controller | changed 2025-10-18 00:25:34.058675 | 2025-10-18 00:25:34.058839 | TASK [include_role : prepare-workspace] 2025-10-18 00:25:34.093445 | controller | ok 2025-10-18 00:25:34.128395 | 2025-10-18 00:25:34.128586 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-18 00:25:34.382152 | controller | ok 2025-10-18 00:25:34.397226 | 2025-10-18 00:25:34.397445 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-18 00:25:47.058484 | controller | Output suppressed because no_log was given 2025-10-18 00:25:47.069708 | 2025-10-18 00:25:47.069872 | TASK [include_role : prepare-workspace-openshift] 2025-10-18 00:25:47.096595 | controller | skipping: Conditional result was False 2025-10-18 00:25:47.121001 | 2025-10-18 00:25:47.121143 | PLAY [all:!appliance] 2025-10-18 00:25:47.140267 | 2025-10-18 00:25:47.140448 | TASK [Run add-build-sshkey role (RSA)] 2025-10-18 00:25:47.172425 | controller | ok 2025-10-18 00:25:47.188709 | 2025-10-18 00:25:47.188949 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-18 00:25:47.484099 | controller -> localhost | ok 2025-10-18 00:25:47.494817 | 2025-10-18 00:25:47.495061 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-18 00:25:47.532502 | controller | ok 2025-10-18 00:25:47.554032 | controller | included: /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-18 00:25:47.564647 | 2025-10-18 00:25:47.564824 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-18 00:25:48.042815 | controller -> localhost | Generating public/private rsa key pair. 2025-10-18 00:25:48.043143 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/work/40705bb6178648659304d2b9a6f157f3_id_rsa. 2025-10-18 00:25:48.043207 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/work/40705bb6178648659304d2b9a6f157f3_id_rsa.pub. 2025-10-18 00:25:48.043255 | controller -> localhost | The key fingerprint is: 2025-10-18 00:25:48.043301 | controller -> localhost | SHA256:W1bTJtbgHb1AdwOrTFZcSokKQygVHQXkhkF7d4u7wMs zuul-build-sshkey 2025-10-18 00:25:48.043343 | controller -> localhost | The key's randomart image is: 2025-10-18 00:25:48.043383 | controller -> localhost | +---[RSA 2048]----+ 2025-10-18 00:25:48.043424 | controller -> localhost | | o=*=+. ====.| 2025-10-18 00:25:48.043464 | controller -> localhost | | . .=+ ooO+.+| 2025-10-18 00:25:48.043503 | controller -> localhost | | .o +o..+*o* .| 2025-10-18 00:25:48.043541 | controller -> localhost | | o ..*oo+ . | 2025-10-18 00:25:48.043573 | controller -> localhost | | S.o+ | 2025-10-18 00:25:48.043617 | controller -> localhost | | . +. | 2025-10-18 00:25:48.043657 | controller -> localhost | | o.. | 2025-10-18 00:25:48.043697 | controller -> localhost | | . o . | 2025-10-18 00:25:48.043754 | controller -> localhost | | E . | 2025-10-18 00:25:48.043804 | controller -> localhost | +----[SHA256]-----+ 2025-10-18 00:25:48.043894 | controller -> localhost | ok: Runtime: 0:00:00.053407 2025-10-18 00:25:48.059132 | 2025-10-18 00:25:48.059305 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-18 00:25:48.094680 | controller | ok 2025-10-18 00:25:48.110112 | controller | included: /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-18 00:25:48.124461 | 2025-10-18 00:25:48.124612 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-18 00:25:48.150046 | controller | skipping: Conditional result was False 2025-10-18 00:25:48.159942 | 2025-10-18 00:25:48.160046 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-18 00:25:48.607444 | controller | changed 2025-10-18 00:25:48.615693 | 2025-10-18 00:25:48.615808 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-18 00:25:48.858537 | controller | ok 2025-10-18 00:25:48.872420 | 2025-10-18 00:25:48.872706 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-18 00:25:49.550313 | controller | changed 2025-10-18 00:25:49.565984 | 2025-10-18 00:25:49.566123 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-18 00:25:50.261316 | controller | changed 2025-10-18 00:25:50.275977 | 2025-10-18 00:25:50.276112 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-18 00:25:50.304466 | controller | skipping: Conditional result was False 2025-10-18 00:25:50.322188 | 2025-10-18 00:25:50.322362 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-18 00:25:50.757614 | controller -> localhost | changed 2025-10-18 00:25:50.770826 | 2025-10-18 00:25:50.771057 | TASK [add-build-sshkey : Add back temp key] 2025-10-18 00:25:51.049258 | controller -> localhost | Identity added: /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/work/40705bb6178648659304d2b9a6f157f3_id_rsa (zuul-build-sshkey) 2025-10-18 00:25:51.049487 | controller -> localhost | ok: Runtime: 0:00:00.009147 2025-10-18 00:25:51.056244 | 2025-10-18 00:25:51.056316 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-18 00:25:51.445116 | controller | ok 2025-10-18 00:25:51.463844 | 2025-10-18 00:25:51.464219 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-18 00:25:51.492117 | controller | skipping: Conditional result was False 2025-10-18 00:25:51.510051 | 2025-10-18 00:25:51.510159 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-18 00:25:51.532607 | controller | ok 2025-10-18 00:25:51.553959 | 2025-10-18 00:25:51.554069 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-18 00:25:51.813589 | controller -> localhost | ok 2025-10-18 00:25:51.829323 | 2025-10-18 00:25:51.829645 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-18 00:25:51.865639 | controller | ok 2025-10-18 00:25:51.885206 | controller | included: /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-18 00:25:51.895325 | 2025-10-18 00:25:51.895452 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-18 00:25:52.217854 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-18 00:25:52.218106 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/work/40705bb6178648659304d2b9a6f157f3_id_ecdsa. 2025-10-18 00:25:52.218151 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/work/40705bb6178648659304d2b9a6f157f3_id_ecdsa.pub. 2025-10-18 00:25:52.218212 | controller -> localhost | The key fingerprint is: 2025-10-18 00:25:52.218249 | controller -> localhost | SHA256:4wMCeXmSTIPsWaO2BQ2d+JEhnu/Yr62cBi/3kJUaBg8 zuul-build-sshkey 2025-10-18 00:25:52.218284 | controller -> localhost | The key's randomart image is: 2025-10-18 00:25:52.218316 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-18 00:25:52.218349 | controller -> localhost | | .o*++ | 2025-10-18 00:25:52.218379 | controller -> localhost | | .=*O+ | 2025-10-18 00:25:52.218411 | controller -> localhost | | .E**o. | 2025-10-18 00:25:52.218442 | controller -> localhost | | =Boo . | 2025-10-18 00:25:52.218471 | controller -> localhost | | . o* + S | 2025-10-18 00:25:52.218503 | controller -> localhost | | o= * o . | 2025-10-18 00:25:52.218536 | controller -> localhost | | .o* o | 2025-10-18 00:25:52.218571 | controller -> localhost | | ..+= . | 2025-10-18 00:25:52.218603 | controller -> localhost | | +=++ | 2025-10-18 00:25:52.218633 | controller -> localhost | +----[SHA256]-----+ 2025-10-18 00:25:52.218700 | controller -> localhost | ok: Runtime: 0:00:00.015127 2025-10-18 00:25:52.227501 | 2025-10-18 00:25:52.227629 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-18 00:25:52.259602 | controller | ok 2025-10-18 00:25:52.272693 | controller | included: /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-18 00:25:52.285023 | 2025-10-18 00:25:52.285169 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-18 00:25:52.310070 | controller | skipping: Conditional result was False 2025-10-18 00:25:52.317284 | 2025-10-18 00:25:52.317398 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-18 00:25:52.666823 | controller | changed 2025-10-18 00:25:52.674582 | 2025-10-18 00:25:52.674739 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-18 00:25:52.922936 | controller | ok 2025-10-18 00:25:52.930903 | 2025-10-18 00:25:52.931032 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-18 00:25:53.577839 | controller | changed 2025-10-18 00:25:53.587082 | 2025-10-18 00:25:53.587241 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-18 00:25:54.203679 | controller | changed 2025-10-18 00:25:54.254056 | 2025-10-18 00:25:54.254190 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-18 00:25:54.290989 | controller | skipping: Conditional result was False 2025-10-18 00:25:54.301082 | 2025-10-18 00:25:54.301208 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-18 00:25:54.573707 | controller -> localhost | changed 2025-10-18 00:25:54.588783 | 2025-10-18 00:25:54.588941 | TASK [add-build-sshkey : Add back temp key] 2025-10-18 00:25:54.902587 | controller -> localhost | Identity added: /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/work/40705bb6178648659304d2b9a6f157f3_id_ecdsa (zuul-build-sshkey) 2025-10-18 00:25:54.902995 | controller -> localhost | ok: Runtime: 0:00:00.015752 2025-10-18 00:25:54.912145 | 2025-10-18 00:25:54.912279 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-18 00:25:55.110023 | controller | ok 2025-10-18 00:25:55.116223 | 2025-10-18 00:25:55.116347 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-18 00:25:55.162042 | controller | skipping: Conditional result was False 2025-10-18 00:25:55.173989 | 2025-10-18 00:25:55.174128 | TASK [include_role : remove-zuul-sshkey] 2025-10-18 00:25:55.199870 | controller | skipping: Conditional result was False 2025-10-18 00:25:55.207783 | 2025-10-18 00:25:55.207914 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-18 00:25:55.449125 | controller | ok: "logs" 2025-10-18 00:25:55.449403 | controller | ok: All items complete 2025-10-18 00:25:55.449432 | 2025-10-18 00:25:55.636263 | controller | ok: "artifacts" 2025-10-18 00:25:55.844191 | controller | ok: "docs" 2025-10-18 00:25:55.861529 | 2025-10-18 00:25:55.861765 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-18 00:25:56.117954 | controller | changed: "logs" 2025-10-18 00:25:56.328006 | controller | changed: "artifacts" 2025-10-18 00:25:56.544789 | controller | changed: "docs" 2025-10-18 00:25:56.593506 | 2025-10-18 00:25:56.593608 | PLAY RECAP 2025-10-18 00:25:56.593665 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-18 00:25:56.593692 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-18 00:25:56.593721 | 2025-10-18 00:25:56.733982 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-18 00:25:56.734880 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-18 00:25:57.392040 | 2025-10-18 00:25:57.392178 | PLAY [all] 2025-10-18 00:25:57.417154 | 2025-10-18 00:25:57.417296 | TASK [Install binary dependencies] 2025-10-18 00:25:57.474566 | controller | ok 2025-10-18 00:25:57.495993 | 2025-10-18 00:25:57.496131 | TASK [bindep : Include find tasks] 2025-10-18 00:25:57.527387 | controller | ok 2025-10-18 00:25:57.536882 | controller | included: /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-18 00:25:57.543766 | 2025-10-18 00:25:57.543832 | TASK [bindep : Look for bindep.txt] 2025-10-18 00:25:57.913399 | controller | ok 2025-10-18 00:25:57.922204 | 2025-10-18 00:25:57.922354 | TASK [bindep : Define bindep_file fact] 2025-10-18 00:25:57.938494 | controller | skipping: Conditional result was False 2025-10-18 00:25:57.947934 | 2025-10-18 00:25:57.948095 | TASK [bindep : Look for other-requirements.txt] 2025-10-18 00:25:58.179546 | controller | ok 2025-10-18 00:25:58.192934 | 2025-10-18 00:25:58.193058 | TASK [bindep : Define bindep_file fact] 2025-10-18 00:25:58.218191 | controller | skipping: Conditional result was False 2025-10-18 00:25:58.227493 | 2025-10-18 00:25:58.227593 | TASK [bindep : Look for bindep fallback file] 2025-10-18 00:25:58.263183 | controller | skipping: Conditional result was False 2025-10-18 00:25:58.273913 | 2025-10-18 00:25:58.274038 | TASK [bindep : Define bindep_file fact] 2025-10-18 00:25:58.299376 | controller | skipping: Conditional result was False 2025-10-18 00:25:58.307812 | 2025-10-18 00:25:58.307964 | TASK [bindep : Include bindep tasks] 2025-10-18 00:25:58.333897 | controller | skipping: Conditional result was False 2025-10-18 00:25:58.340199 | 2025-10-18 00:25:58.340308 | TASK [bindep : Include install tasks] 2025-10-18 00:25:58.365104 | controller | skipping: Conditional result was False 2025-10-18 00:25:58.371861 | 2025-10-18 00:25:58.371980 | LOOP [bindep : Include package tasks] 2025-10-18 00:25:58.440752 | 2025-10-18 00:25:58.440948 | TASK [Run test-setup role] 2025-10-18 00:25:58.462906 | controller | ok 2025-10-18 00:25:58.484125 | 2025-10-18 00:25:58.484252 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-18 00:25:58.714238 | controller | ok 2025-10-18 00:25:58.724939 | 2025-10-18 00:25:58.725073 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-18 00:25:59.277228 | controller | skipping: Conditional result was False 2025-10-18 00:25:59.323428 | 2025-10-18 00:25:59.323550 | PLAY RECAP 2025-10-18 00:25:59.323605 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-18 00:25:59.323635 | 2025-10-18 00:25:59.469016 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-18 00:25:59.470257 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-18 00:26:00.103617 | 2025-10-18 00:26:00.103842 | PLAY [controller] 2025-10-18 00:26:00.125046 | 2025-10-18 00:26:00.125193 | TASK [Create the /root directory] 2025-10-18 00:26:00.548848 | controller | ok 2025-10-18 00:26:00.558076 | 2025-10-18 00:26:00.558230 | TASK [Install glibc-langpack-en] 2025-10-18 00:26:04.691927 | controller | ok: Nothing to do 2025-10-18 00:26:04.704455 | 2025-10-18 00:26:04.704781 | TASK [Ensure controller directory exists] 2025-10-18 00:26:04.932117 | controller | changed 2025-10-18 00:26:04.937918 | 2025-10-18 00:26:04.937985 | TASK [Install container runtime] 2025-10-18 00:26:04.991031 | controller | ok 2025-10-18 00:26:05.040773 | 2025-10-18 00:26:05.040919 | LOOP [ensure-podman : Find distribution installation] 2025-10-18 00:26:05.097129 | controller | ok: "/var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-18 00:26:05.108028 | controller | included: /var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-18 00:26:05.114639 | 2025-10-18 00:26:05.114707 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-18 00:27:14.137851 | controller | changed 2025-10-18 00:27:14.147517 | 2025-10-18 00:27:14.147672 | TASK [ensure-podman : Fetch podman version] 2025-10-18 00:27:14.704034 | controller | Client: Podman Engine 2025-10-18 00:27:14.738306 | controller | Version: 4.6.2 2025-10-18 00:27:14.738367 | controller | API Version: 4.6.2 2025-10-18 00:27:14.738381 | controller | Go Version: go1.19.12 2025-10-18 00:27:14.738407 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-18 00:27:14.738420 | controller | OS/Arch: linux/amd64 2025-10-18 00:27:15.186110 | controller | ok: Runtime: 0:00:00.201979 2025-10-18 00:27:15.201188 | 2025-10-18 00:27:15.201368 | TASK [ensure-podman : Print podman version installed] 2025-10-18 00:27:15.245771 | Podman version: Client: Podman Engine 2025-10-18 00:27:15.246112 | Version: 4.6.2 2025-10-18 00:27:15.246208 | API Version: 4.6.2 2025-10-18 00:27:15.246264 | Go Version: go1.19.12 2025-10-18 00:27:15.246320 | Built: Mon Aug 28 19:38:31 2023 2025-10-18 00:27:15.246364 | OS/Arch: linux/amd64 2025-10-18 00:27:15.259819 | 2025-10-18 00:27:15.259992 | TASK [ensure-podman : Validate podman engine] 2025-10-18 00:27:15.807263 | controller | skipping: Conditional result was False 2025-10-18 00:27:15.815287 | 2025-10-18 00:27:15.815371 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-18 00:27:15.832108 | controller | skipping: Conditional result was False 2025-10-18 00:27:15.845947 | 2025-10-18 00:27:15.846099 | TASK [Ensure python3.8 is present] 2025-10-18 00:27:15.871234 | controller | skipping: Conditional result was False 2025-10-18 00:27:15.880548 | 2025-10-18 00:27:15.880667 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-18 00:27:15.906689 | controller | ok 2025-10-18 00:27:15.937325 | 2025-10-18 00:27:15.937499 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-18 00:27:17.550605 | controller | ok: Nothing to do 2025-10-18 00:27:17.563663 | 2025-10-18 00:27:17.563839 | TASK [our-ensure-python : Also install python3-devel] 2025-10-18 00:27:28.579702 | controller | changed 2025-10-18 00:27:28.594582 | 2025-10-18 00:27:28.594747 | TASK [Run ensure-virtualenv role] 2025-10-18 00:27:28.632803 | controller | ok 2025-10-18 00:27:28.654325 | 2025-10-18 00:27:28.654446 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-18 00:27:28.893594 | controller | /usr/bin/virtualenv 2025-10-18 00:27:29.189035 | controller | ok: Runtime: 0:00:00.007176 2025-10-18 00:27:29.200446 | 2025-10-18 00:27:29.200609 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-18 00:27:29.230912 | controller | skipping: Conditional result was False 2025-10-18 00:27:29.231373 | controller | ok: All items complete 2025-10-18 00:27:29.231416 | 2025-10-18 00:27:29.317451 | 2025-10-18 00:27:29.317680 | TASK [Find the full path of the Python interpreter] 2025-10-18 00:27:29.527756 | controller | /usr/bin/python3 2025-10-18 00:27:29.850494 | controller | ok 2025-10-18 00:27:29.865711 | 2025-10-18 00:27:29.865960 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-18 00:27:30.802359 | controller | created virtual environment CPython3.11.0.final.0-64 in 497ms 2025-10-18 00:27:30.827019 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-18 00:27:30.827064 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv) 2025-10-18 00:27:30.827073 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-18 00:27:30.827086 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-18 00:27:30.939164 | controller | changed 2025-10-18 00:27:30.954380 | 2025-10-18 00:27:30.954529 | TASK [Set selinux package] 2025-10-18 00:27:30.986100 | controller | ok 2025-10-18 00:27:30.992158 | 2025-10-18 00:27:30.992271 | TASK [Set selinux package (Fedora)] 2025-10-18 00:27:31.034310 | controller | ok 2025-10-18 00:27:31.040160 | 2025-10-18 00:27:31.040273 | TASK [Install selinux into virtualenv] 2025-10-18 00:27:44.854280 | controller | Collecting selinux-please-lie-to-me 2025-10-18 00:27:57.122803 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-18 00:27:57.464445 | controller | Collecting setuptools<50.0.0 2025-10-18 00:27:57.471690 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-18 00:27:57.527033 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 16.1 MB/s eta 0:00:00 2025-10-18 00:27:57.647653 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-18 00:27:57.648399 | controller | Attempting uninstall: setuptools 2025-10-18 00:27:57.654084 | controller | Found existing installation: setuptools 62.6.0 2025-10-18 00:27:57.755924 | controller | Uninstalling setuptools-62.6.0: 2025-10-18 00:27:57.769608 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-18 00:27:58.212624 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-18 00:28:09.481905 | controller | 2025-10-18 00:28:09.586154 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-18 00:28:09.586207 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-18 00:28:09.625526 | controller | ok: Runtime: 0:00:38.333020 2025-10-18 00:28:09.636377 | 2025-10-18 00:28:09.636554 | TASK [Install pytest-forked into virtualenv] 2025-10-18 00:28:21.729811 | controller | Collecting pytest-forked 2025-10-18 00:28:32.062300 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-18 00:28:32.177948 | controller | Collecting py 2025-10-18 00:28:32.192932 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-18 00:28:32.222291 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.5 MB/s eta 0:00:00 2025-10-18 00:28:32.335679 | controller | Collecting pytest>=3.10 2025-10-18 00:28:32.341004 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-18 00:28:32.356464 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 28.9 MB/s eta 0:00:00 2025-10-18 00:28:32.409960 | controller | Collecting iniconfig>=1 2025-10-18 00:28:32.413920 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-18 00:28:32.458656 | controller | Collecting packaging>=20 2025-10-18 00:28:32.462253 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-18 00:28:32.471042 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.7 MB/s eta 0:00:00 2025-10-18 00:28:32.511787 | controller | Collecting pluggy<2,>=1.5 2025-10-18 00:28:32.516244 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-18 00:28:32.565013 | controller | Collecting pygments>=2.7.2 2025-10-18 00:28:32.568573 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-18 00:28:32.609043 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 33.2 MB/s eta 0:00:00 2025-10-18 00:28:32.678729 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-18 00:28:33.777312 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0 2025-10-18 00:28:33.786118 | controller | 2025-10-18 00:28:33.859992 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-18 00:28:33.860034 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-18 00:28:34.215269 | controller | ok: Runtime: 0:00:23.931837 2025-10-18 00:28:34.222072 | 2025-10-18 00:28:34.222211 | TASK [Update pip] 2025-10-18 00:28:34.770889 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-18 00:28:44.435921 | controller | Collecting pip 2025-10-18 00:28:56.633754 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-18 00:28:56.709815 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.9 MB/s eta 0:00:00 2025-10-18 00:28:56.773684 | controller | Installing collected packages: pip 2025-10-18 00:28:56.773845 | controller | Attempting uninstall: pip 2025-10-18 00:28:56.775989 | controller | Found existing installation: pip 22.2.2 2025-10-18 00:28:56.914671 | controller | Uninstalling pip-22.2.2: 2025-10-18 00:28:56.930458 | controller | Successfully uninstalled pip-22.2.2 2025-10-18 00:28:57.787462 | controller | Successfully installed pip-25.2 2025-10-18 00:28:58.293400 | controller | ok: Runtime: 0:00:23.396753 2025-10-18 00:28:58.301798 | 2025-10-18 00:28:58.301932 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-18 00:28:58.542333 | controller | changed 2025-10-18 00:28:58.548676 | 2025-10-18 00:28:58.548799 | TASK [Install ansible into virtualenv] 2025-10-18 00:28:59.073386 | controller | Processing ./src/github.com/ansible/ansible 2025-10-18 00:28:59.077210 | controller | Installing build dependencies: started 2025-10-18 00:29:21.596197 | controller | Installing build dependencies: finished with status 'done' 2025-10-18 00:29:21.597269 | controller | Getting requirements to build wheel: started 2025-10-18 00:29:22.352715 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-18 00:29:22.353593 | controller | Preparing metadata (pyproject.toml): started 2025-10-18 00:29:22.846160 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-18 00:29:22.851528 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-10-18 00:29:22.855949 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-18 00:29:23.092628 | controller | ERROR 2025-10-18 00:29:23.093019 | controller | { 2025-10-18 00:29:23.093155 | controller | "delta": "0:00:24.165615", 2025-10-18 00:29:23.093222 | controller | "end": "2025-10-18 00:29:22.924239", 2025-10-18 00:29:23.093267 | controller | "msg": "non-zero return code", 2025-10-18 00:29:23.093329 | controller | "rc": 1, 2025-10-18 00:29:23.093365 | controller | "start": "2025-10-18 00:28:58.758624" 2025-10-18 00:29:23.093398 | controller | } failure 2025-10-18 00:29:23.096473 | 2025-10-18 00:29:23.096602 | PLAY RECAP 2025-10-18 00:29:23.096714 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-18 00:29:23.096809 | 2025-10-18 00:29:23.220809 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-18 00:29:23.222490 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-18 00:29:23.819820 | 2025-10-18 00:29:23.819977 | PLAY [all] 2025-10-18 00:29:23.845051 | 2025-10-18 00:29:23.845212 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-18 00:29:24.104577 | controller | changed: non-zero return code 2025-10-18 00:29:24.110919 | 2025-10-18 00:29:24.111013 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-18 00:29:24.136158 | controller | skipping: Conditional result was False 2025-10-18 00:29:24.143517 | 2025-10-18 00:29:24.143636 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-18 00:29:24.177030 | 2025-10-18 00:29:24.177214 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-18 00:29:24.201573 | 2025-10-18 00:29:24.201820 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-18 00:29:24.217056 | controller | skipping: Conditional result was False 2025-10-18 00:29:24.227341 | 2025-10-18 00:29:24.227506 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-18 00:29:24.259591 | 2025-10-18 00:29:24.259826 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-18 00:29:24.285032 | controller | skipping: Conditional result was False 2025-10-18 00:29:24.292165 | 2025-10-18 00:29:24.292316 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-18 00:29:24.317368 | controller | skipping: Conditional result was False 2025-10-18 00:29:24.324814 | 2025-10-18 00:29:24.324952 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-18 00:29:24.339694 | controller | skipping: Conditional result was False 2025-10-18 00:29:24.367556 | 2025-10-18 00:29:24.367690 | PLAY RECAP 2025-10-18 00:29:24.367769 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-18 00:29:24.367794 | 2025-10-18 00:29:24.482105 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-18 00:29:24.483169 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-18 00:29:25.106462 | 2025-10-18 00:29:25.106615 | PLAY [all:!appliance*] 2025-10-18 00:29:25.130372 | 2025-10-18 00:29:25.130525 | TASK [unregister the node] 2025-10-18 00:29:25.663119 | controller | skipping: Conditional result was False 2025-10-18 00:29:25.669229 | 2025-10-18 00:29:25.669352 | TASK [include_role : fetch-output] 2025-10-18 00:29:25.702843 | controller | ok 2025-10-18 00:29:25.726609 | 2025-10-18 00:29:25.726767 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-18 00:29:25.772195 | controller | skipping: Conditional result was False 2025-10-18 00:29:25.778915 | 2025-10-18 00:29:25.779020 | TASK [fetch-output : Set log path for single node] 2025-10-18 00:29:25.821007 | controller | ok 2025-10-18 00:29:25.827959 | 2025-10-18 00:29:25.828073 | LOOP [fetch-output : Ensure local output dirs] 2025-10-18 00:29:26.255217 | controller -> localhost | ok: "/var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/work/logs" 2025-10-18 00:29:26.476470 | controller -> localhost | changed: "/var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/work/artifacts" 2025-10-18 00:29:26.694348 | controller -> localhost | changed: "/var/lib/zuul/builds/40705bb6178648659304d2b9a6f157f3/work/docs" 2025-10-18 00:29:26.711029 | 2025-10-18 00:29:26.711187 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-18 00:29:27.391412 | controller | changed: 2025-10-18 00:29:27.391632 | controller | .d..t...... ./ 2025-10-18 00:29:27.391661 | controller | cd+++++++++ controller/ 2025-10-18 00:29:27.391695 | controller | changed: All items complete 2025-10-18 00:29:27.391716 | 2025-10-18 00:29:27.936871 | controller | changed: .d..t...... ./ 2025-10-18 00:29:28.445543 | controller | changed: .d..t...... ./ 2025-10-18 00:29:28.473999 | 2025-10-18 00:29:28.474186 | TASK [include_role : fetch-output-openshift] 2025-10-18 00:29:28.491053 | controller | skipping: Conditional result was False 2025-10-18 00:29:28.504590 | 2025-10-18 00:29:28.504837 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-18 00:29:28.534523 | controller | skipping: Conditional result was False 2025-10-18 00:29:28.543790 | controller | skipping: Conditional result was False 2025-10-18 00:29:28.583250 | 2025-10-18 00:29:28.583376 | PLAY [localhost] 2025-10-18 00:29:28.596369 | 2025-10-18 00:29:28.596467 | TASK [Run Zuul manifest role] 2025-10-18 00:29:28.615076 | localhost | ok 2025-10-18 00:29:28.629380 | 2025-10-18 00:29:28.629483 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-18 00:29:29.068241 | localhost | changed 2025-10-18 00:29:29.073553 | 2025-10-18 00:29:29.073654 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-18 00:29:29.116602 | localhost | ok 2025-10-18 00:29:29.126717 | 2025-10-18 00:29:29.126888 | TASK [Set zuul-log-path fact] 2025-10-18 00:29:29.150935 | localhost | ok 2025-10-18 00:29:29.173106 | 2025-10-18 00:29:29.173277 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-18 00:29:29.205847 | localhost | ok 2025-10-18 00:29:29.214837 | 2025-10-18 00:29:29.214968 | LOOP [Run upload-logs-swift role] 2025-10-18 00:29:29.240359 | localhost | Output suppressed because no_log was given 2025-10-18 00:29:29.268079 | 2025-10-18 00:29:29.268212 | TASK [Set zuul-log-path fact] 2025-10-18 00:29:29.294100 | localhost | skipping: Conditional result was False 2025-10-18 00:29:29.301833 | 2025-10-18 00:29:29.301976 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-18 00:29:29.780634 | localhost -> localhost | ok: Runtime: 0:00:00.011667 2025-10-18 00:29:29.790567 | 2025-10-18 00:29:29.790777 | TASK [upload-logs-swift : Upload logs to swift]