2025-10-21 00:19:50.442547 | Job console starting... 2025-10-21 00:19:50.451910 | Updating repositories 2025-10-21 00:19:50.574135 | Preparing job workspace 2025-10-21 00:19:53.973697 | Running Ansible setup... 2025-10-21 00:20:01.696722 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-21 00:20:02.279939 | 2025-10-21 00:20:02.280065 | PLAY [localhost] 2025-10-21 00:20:02.288803 | 2025-10-21 00:20:02.288884 | TASK [Gathering Facts] 2025-10-21 00:20:03.198488 | localhost | ok 2025-10-21 00:20:03.213502 | 2025-10-21 00:20:03.213628 | TASK [Setup log path fact] 2025-10-21 00:20:03.231696 | localhost | ok 2025-10-21 00:20:03.245946 | 2025-10-21 00:20:03.246091 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-21 00:20:03.274370 | localhost | ok 2025-10-21 00:20:03.282349 | 2025-10-21 00:20:03.282426 | TASK [emit-job-header : Print job information] 2025-10-21 00:20:03.320344 | # Job Information 2025-10-21 00:20:03.320491 | Ansible Version: 2.15.12 2025-10-21 00:20:03.320522 | Job: ansible-test-sanity-docker-devel 2025-10-21 00:20:03.320544 | Pipeline: periodic 2025-10-21 00:20:03.320562 | Executor: ze04.softwarefactory-project.io 2025-10-21 00:20:03.320580 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-21 00:20:03.320600 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/0f6/ansible/0f63257d49374945be95b9eb2b8f5fc2/ 2025-10-21 00:20:03.320619 | Event ID: b84420a1d3514a69852f0a57fcb9cd72 2025-10-21 00:20:03.324787 | 2025-10-21 00:20:03.324865 | LOOP [emit-job-header : Print node information] 2025-10-21 00:20:03.435004 | localhost | ok: 2025-10-21 00:20:03.435257 | localhost | # Node Information 2025-10-21 00:20:03.435305 | localhost | Inventory Hostname: controller 2025-10-21 00:20:03.435334 | localhost | Hostname: np0005496194 2025-10-21 00:20:03.435362 | localhost | Username: zuul 2025-10-21 00:20:03.435505 | localhost | Distro: Fedora 37 2025-10-21 00:20:03.435552 | localhost | Provider: ansible-vexxhost-ams1 2025-10-21 00:20:03.435582 | localhost | Region: ams1 2025-10-21 00:20:03.435611 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-21 00:20:03.435645 | localhost | Product Name: OpenStack Nova 2025-10-21 00:20:03.435698 | localhost | Interface IP: 38.129.16.97 2025-10-21 00:20:03.453552 | 2025-10-21 00:20:03.453749 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-21 00:20:03.867714 | localhost -> localhost | changed 2025-10-21 00:20:03.879734 | 2025-10-21 00:20:03.879910 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-21 00:20:04.794470 | localhost -> localhost | changed 2025-10-21 00:20:04.816763 | 2025-10-21 00:20:04.816887 | PLAY [all:!appliance*] 2025-10-21 00:20:04.849000 | 2025-10-21 00:20:04.849126 | TASK [include_role : start-zuul-console] 2025-10-21 00:20:04.868360 | controller | ok 2025-10-21 00:20:04.882751 | 2025-10-21 00:20:04.882870 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-21 00:20:05.859067 | controller | ok 2025-10-21 00:20:05.870794 | 2025-10-21 00:20:05.870955 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-21 00:20:08.164666 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-21 00:20:08.171199 | 2025-10-21 00:20:08.171274 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-21 00:20:08.526546 | controller | skipping: Conditional result was False 2025-10-21 00:20:08.534384 | 2025-10-21 00:20:08.534506 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-21 00:20:08.559821 | controller | skipping: Conditional result was False 2025-10-21 00:20:08.568375 | 2025-10-21 00:20:08.568502 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-21 00:20:08.592412 | controller | skipping: Conditional result was False 2025-10-21 00:20:08.600978 | 2025-10-21 00:20:08.601115 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-21 00:20:08.629203 | controller | skipping: Conditional result was False 2025-10-21 00:20:08.642586 | 2025-10-21 00:20:08.642825 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-21 00:20:08.670659 | controller | skipping: Conditional result was False 2025-10-21 00:20:08.687785 | 2025-10-21 00:20:08.688022 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-21 00:20:08.714756 | controller | skipping: Conditional result was False 2025-10-21 00:20:08.732345 | 2025-10-21 00:20:08.732493 | TASK [Disable Fedora Modular] 2025-10-21 00:20:09.801788 | controller | changed 2025-10-21 00:20:09.810541 | 2025-10-21 00:20:09.810647 | TASK [Enable EPEL] 2025-10-21 00:20:09.835821 | controller | skipping: Conditional result was False 2025-10-21 00:20:09.844669 | 2025-10-21 00:20:09.844797 | TASK [Register the RHEL node] 2025-10-21 00:20:10.256214 | 2025-10-21 00:20:10.256373 | TASK [Show the subscription-manager status] 2025-10-21 00:20:10.622273 | controller | skipping: Conditional result was False 2025-10-21 00:20:10.634448 | 2025-10-21 00:20:10.634559 | TASK [Enable EPEL on RHEL] 2025-10-21 00:20:11.001380 | controller | skipping: Conditional result was False 2025-10-21 00:20:11.015099 | 2025-10-21 00:20:11.015277 | TASK [Install git and tox] 2025-10-21 00:21:57.192972 | controller | changed 2025-10-21 00:21:57.202102 | 2025-10-21 00:21:57.202191 | TASK [include_role : prepare-workspace] 2025-10-21 00:21:57.234636 | controller | ok 2025-10-21 00:21:57.271586 | 2025-10-21 00:21:57.271726 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-21 00:21:58.051019 | controller | ok 2025-10-21 00:21:58.062912 | 2025-10-21 00:21:58.063079 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-21 00:22:14.237639 | controller | Output suppressed because no_log was given 2025-10-21 00:22:14.254288 | 2025-10-21 00:22:14.254383 | TASK [include_role : prepare-workspace-openshift] 2025-10-21 00:22:14.279735 | controller | skipping: Conditional result was False 2025-10-21 00:22:14.372403 | 2025-10-21 00:22:14.372563 | PLAY [all:!appliance] 2025-10-21 00:22:14.398111 | 2025-10-21 00:22:14.398256 | TASK [Run add-build-sshkey role (RSA)] 2025-10-21 00:22:14.435896 | controller | ok 2025-10-21 00:22:14.455743 | 2025-10-21 00:22:14.455885 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-21 00:22:14.715972 | controller -> localhost | ok 2025-10-21 00:22:14.726534 | 2025-10-21 00:22:14.726705 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-21 00:22:14.764331 | controller | ok 2025-10-21 00:22:14.786071 | controller | included: /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-21 00:22:14.795451 | 2025-10-21 00:22:14.795536 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-21 00:22:15.271906 | controller -> localhost | Generating public/private rsa key pair. 2025-10-21 00:22:15.272184 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/work/0f63257d49374945be95b9eb2b8f5fc2_id_rsa. 2025-10-21 00:22:15.272224 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/work/0f63257d49374945be95b9eb2b8f5fc2_id_rsa.pub. 2025-10-21 00:22:15.272249 | controller -> localhost | The key fingerprint is: 2025-10-21 00:22:15.272271 | controller -> localhost | SHA256:IeSkWg5WvSGrGjWR+m+Oe06t+/CYUi2kTdN+Mjq4igs zuul-build-sshkey 2025-10-21 00:22:15.272292 | controller -> localhost | The key's randomart image is: 2025-10-21 00:22:15.272313 | controller -> localhost | +---[RSA 2048]----+ 2025-10-21 00:22:15.272333 | controller -> localhost | | ...o | 2025-10-21 00:22:15.272354 | controller -> localhost | | o..=o | 2025-10-21 00:22:15.272375 | controller -> localhost | | .o.o+oo. | 2025-10-21 00:22:15.272395 | controller -> localhost | |..o== o. . | 2025-10-21 00:22:15.272414 | controller -> localhost | | o.B.+ S | 2025-10-21 00:22:15.272442 | controller -> localhost | |. + +.= . | 2025-10-21 00:22:15.272468 | controller -> localhost | |Eo +oo.+ | 2025-10-21 00:22:15.272489 | controller -> localhost | |+ oo** | 2025-10-21 00:22:15.272509 | controller -> localhost | |+o+OB+o | 2025-10-21 00:22:15.272532 | controller -> localhost | +----[SHA256]-----+ 2025-10-21 00:22:15.272592 | controller -> localhost | ok: Runtime: 0:00:00.056247 2025-10-21 00:22:15.280173 | 2025-10-21 00:22:15.280311 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-21 00:22:15.310545 | controller | ok 2025-10-21 00:22:15.321203 | controller | included: /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-21 00:22:15.332890 | 2025-10-21 00:22:15.333003 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-21 00:22:15.357110 | controller | skipping: Conditional result was False 2025-10-21 00:22:15.364794 | 2025-10-21 00:22:15.364899 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-21 00:22:16.463502 | controller | changed 2025-10-21 00:22:16.475155 | 2025-10-21 00:22:16.475798 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-21 00:22:17.071179 | controller | ok 2025-10-21 00:22:17.077305 | 2025-10-21 00:22:17.077376 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-21 00:22:20.035033 | controller | changed 2025-10-21 00:22:20.051652 | 2025-10-21 00:22:20.051817 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-21 00:22:23.013602 | controller | changed 2025-10-21 00:22:23.022555 | 2025-10-21 00:22:23.022662 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-21 00:22:23.047270 | controller | skipping: Conditional result was False 2025-10-21 00:22:23.053992 | 2025-10-21 00:22:23.054085 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-21 00:22:23.455786 | controller -> localhost | changed 2025-10-21 00:22:23.469762 | 2025-10-21 00:22:23.469981 | TASK [add-build-sshkey : Add back temp key] 2025-10-21 00:22:23.802257 | controller -> localhost | Identity added: /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/work/0f63257d49374945be95b9eb2b8f5fc2_id_rsa (zuul-build-sshkey) 2025-10-21 00:22:23.802488 | controller -> localhost | ok: Runtime: 0:00:00.007428 2025-10-21 00:22:23.810113 | 2025-10-21 00:22:23.810189 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-21 00:22:24.721888 | controller | ok 2025-10-21 00:22:24.732247 | 2025-10-21 00:22:24.732389 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-21 00:22:24.779127 | controller | skipping: Conditional result was False 2025-10-21 00:22:24.796402 | 2025-10-21 00:22:24.796539 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-21 00:22:24.818194 | controller | ok 2025-10-21 00:22:24.841057 | 2025-10-21 00:22:24.841184 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-21 00:22:25.070030 | controller -> localhost | ok 2025-10-21 00:22:25.079235 | 2025-10-21 00:22:25.079343 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-21 00:22:25.114735 | controller | ok 2025-10-21 00:22:25.131838 | controller | included: /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-21 00:22:25.141902 | 2025-10-21 00:22:25.142023 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-21 00:22:25.431339 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-21 00:22:25.431604 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/work/0f63257d49374945be95b9eb2b8f5fc2_id_ecdsa. 2025-10-21 00:22:25.431662 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/work/0f63257d49374945be95b9eb2b8f5fc2_id_ecdsa.pub. 2025-10-21 00:22:25.431715 | controller -> localhost | The key fingerprint is: 2025-10-21 00:22:25.431744 | controller -> localhost | SHA256:0d2B1Q8d0mbaMlgPmLydAvrwoCGR4QIPZrHjkT17CqI zuul-build-sshkey 2025-10-21 00:22:25.431772 | controller -> localhost | The key's randomart image is: 2025-10-21 00:22:25.431798 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-21 00:22:25.431822 | controller -> localhost | |o+..o . o+++.| 2025-10-21 00:22:25.431849 | controller -> localhost | |+o=o o =.+o=o| 2025-10-21 00:22:25.431876 | controller -> localhost | | *.+. o o * X..| 2025-10-21 00:22:25.431904 | controller -> localhost | |. +.o. + . + * o.| 2025-10-21 00:22:25.431931 | controller -> localhost | |.o ...o S . o | 2025-10-21 00:22:25.431975 | controller -> localhost | |o . o. o | 2025-10-21 00:22:25.432002 | controller -> localhost | |E . | 2025-10-21 00:22:25.432026 | controller -> localhost | | | 2025-10-21 00:22:25.432052 | controller -> localhost | | | 2025-10-21 00:22:25.432080 | controller -> localhost | +----[SHA256]-----+ 2025-10-21 00:22:25.432139 | controller -> localhost | ok: Runtime: 0:00:00.008151 2025-10-21 00:22:25.440803 | 2025-10-21 00:22:25.441062 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-21 00:22:25.482022 | controller | ok 2025-10-21 00:22:25.492774 | controller | included: /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-21 00:22:25.504753 | 2025-10-21 00:22:25.504881 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-21 00:22:25.520201 | controller | skipping: Conditional result was False 2025-10-21 00:22:25.529062 | 2025-10-21 00:22:25.529198 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-21 00:22:26.373118 | controller | changed 2025-10-21 00:22:26.387295 | 2025-10-21 00:22:26.387484 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-21 00:22:27.051723 | controller | ok 2025-10-21 00:22:27.061448 | 2025-10-21 00:22:27.061859 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-21 00:22:30.031615 | controller | changed 2025-10-21 00:22:30.052041 | 2025-10-21 00:22:30.052182 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-21 00:22:32.952031 | controller | changed 2025-10-21 00:22:32.960018 | 2025-10-21 00:22:32.960096 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-21 00:22:32.985486 | controller | skipping: Conditional result was False 2025-10-21 00:22:32.994278 | 2025-10-21 00:22:32.994358 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-21 00:22:33.266031 | controller -> localhost | changed 2025-10-21 00:22:33.285227 | 2025-10-21 00:22:33.285351 | TASK [add-build-sshkey : Add back temp key] 2025-10-21 00:22:33.622174 | controller -> localhost | Identity added: /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/work/0f63257d49374945be95b9eb2b8f5fc2_id_ecdsa (zuul-build-sshkey) 2025-10-21 00:22:33.622368 | controller -> localhost | ok: Runtime: 0:00:00.008393 2025-10-21 00:22:33.629077 | 2025-10-21 00:22:33.629159 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-21 00:22:34.302224 | controller | ok 2025-10-21 00:22:34.307890 | 2025-10-21 00:22:34.307990 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-21 00:22:34.332896 | controller | skipping: Conditional result was False 2025-10-21 00:22:34.346261 | 2025-10-21 00:22:34.346385 | TASK [include_role : remove-zuul-sshkey] 2025-10-21 00:22:34.370958 | controller | skipping: Conditional result was False 2025-10-21 00:22:34.377788 | 2025-10-21 00:22:34.377899 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-21 00:22:35.007223 | controller | ok: "logs" 2025-10-21 00:22:35.007732 | controller | ok: All items complete 2025-10-21 00:22:35.007981 | 2025-10-21 00:22:35.567542 | controller | ok: "artifacts" 2025-10-21 00:22:36.166174 | controller | ok: "docs" 2025-10-21 00:22:36.184417 | 2025-10-21 00:22:36.184608 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-21 00:22:36.819193 | controller | changed: "logs" 2025-10-21 00:22:37.384929 | controller | changed: "artifacts" 2025-10-21 00:22:37.960304 | controller | changed: "docs" 2025-10-21 00:22:38.011149 | 2025-10-21 00:22:38.011273 | PLAY RECAP 2025-10-21 00:22:38.011334 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-21 00:22:38.011372 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-21 00:22:38.011398 | 2025-10-21 00:22:38.133476 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-21 00:22:38.134350 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-21 00:22:38.709257 | 2025-10-21 00:22:38.709392 | PLAY [all] 2025-10-21 00:22:38.734344 | 2025-10-21 00:22:38.734478 | TASK [Install binary dependencies] 2025-10-21 00:22:38.795866 | controller | ok 2025-10-21 00:22:38.816479 | 2025-10-21 00:22:38.816609 | TASK [bindep : Include find tasks] 2025-10-21 00:22:38.845957 | controller | ok 2025-10-21 00:22:38.854081 | controller | included: /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-21 00:22:38.860905 | 2025-10-21 00:22:38.860998 | TASK [bindep : Look for bindep.txt] 2025-10-21 00:22:39.730535 | controller | ok 2025-10-21 00:22:39.740326 | 2025-10-21 00:22:39.740451 | TASK [bindep : Define bindep_file fact] 2025-10-21 00:22:39.755388 | controller | skipping: Conditional result was False 2025-10-21 00:22:39.764356 | 2025-10-21 00:22:39.764468 | TASK [bindep : Look for other-requirements.txt] 2025-10-21 00:22:40.336393 | controller | ok 2025-10-21 00:22:40.342018 | 2025-10-21 00:22:40.342107 | TASK [bindep : Define bindep_file fact] 2025-10-21 00:22:40.366804 | controller | skipping: Conditional result was False 2025-10-21 00:22:40.374590 | 2025-10-21 00:22:40.374726 | TASK [bindep : Look for bindep fallback file] 2025-10-21 00:22:40.399370 | controller | skipping: Conditional result was False 2025-10-21 00:22:40.408214 | 2025-10-21 00:22:40.408359 | TASK [bindep : Define bindep_file fact] 2025-10-21 00:22:40.432909 | controller | skipping: Conditional result was False 2025-10-21 00:22:40.441213 | 2025-10-21 00:22:40.441334 | TASK [bindep : Include bindep tasks] 2025-10-21 00:22:40.476195 | controller | skipping: Conditional result was False 2025-10-21 00:22:40.484815 | 2025-10-21 00:22:40.484907 | TASK [bindep : Include install tasks] 2025-10-21 00:22:40.510740 | controller | skipping: Conditional result was False 2025-10-21 00:22:40.521052 | 2025-10-21 00:22:40.521141 | LOOP [bindep : Include package tasks] 2025-10-21 00:22:40.592733 | 2025-10-21 00:22:40.592920 | TASK [Run test-setup role] 2025-10-21 00:22:40.614618 | controller | ok 2025-10-21 00:22:40.638573 | 2025-10-21 00:22:40.638722 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-21 00:22:41.309591 | controller | ok 2025-10-21 00:22:41.327743 | 2025-10-21 00:22:41.327935 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-21 00:22:41.699428 | controller | skipping: Conditional result was False 2025-10-21 00:22:41.746422 | 2025-10-21 00:22:41.746533 | PLAY RECAP 2025-10-21 00:22:41.746591 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-21 00:22:41.746621 | 2025-10-21 00:22:41.872542 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-21 00:22:41.873402 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-21 00:22:42.508965 | 2025-10-21 00:22:42.509100 | PLAY [controller] 2025-10-21 00:22:42.529696 | 2025-10-21 00:22:42.529812 | TASK [Create the /root directory] 2025-10-21 00:22:43.500453 | controller | ok 2025-10-21 00:22:43.506800 | 2025-10-21 00:22:43.506883 | TASK [Install glibc-langpack-en] 2025-10-21 00:22:50.351827 | controller | ok: Nothing to do 2025-10-21 00:22:50.358080 | 2025-10-21 00:22:50.358195 | TASK [Ensure controller directory exists] 2025-10-21 00:22:51.122074 | controller | changed 2025-10-21 00:22:51.140088 | 2025-10-21 00:22:51.140796 | TASK [Install container runtime] 2025-10-21 00:22:51.208617 | controller | ok 2025-10-21 00:22:51.251897 | 2025-10-21 00:22:51.252025 | LOOP [ensure-podman : Find distribution installation] 2025-10-21 00:22:51.281359 | controller | ok: "/var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-21 00:22:51.297104 | controller | included: /var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-21 00:22:51.304299 | 2025-10-21 00:22:51.304415 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-21 00:24:35.744219 | controller | changed 2025-10-21 00:24:35.751570 | 2025-10-21 00:24:35.751657 | TASK [ensure-podman : Fetch podman version] 2025-10-21 00:24:36.827306 | controller | Client: Podman Engine 2025-10-21 00:24:36.862859 | controller | Version: 4.6.2 2025-10-21 00:24:36.862910 | controller | API Version: 4.6.2 2025-10-21 00:24:36.862919 | controller | Go Version: go1.19.12 2025-10-21 00:24:36.862937 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-21 00:24:36.862945 | controller | OS/Arch: linux/amd64 2025-10-21 00:24:37.113908 | controller | ok: Runtime: 0:00:00.242433 2025-10-21 00:24:37.131255 | 2025-10-21 00:24:37.131425 | TASK [ensure-podman : Print podman version installed] 2025-10-21 00:24:37.179542 | Podman version: Client: Podman Engine 2025-10-21 00:24:37.179827 | Version: 4.6.2 2025-10-21 00:24:37.179891 | API Version: 4.6.2 2025-10-21 00:24:37.179937 | Go Version: go1.19.12 2025-10-21 00:24:37.179977 | Built: Mon Aug 28 19:38:31 2023 2025-10-21 00:24:37.180018 | OS/Arch: linux/amd64 2025-10-21 00:24:37.191376 | 2025-10-21 00:24:37.191467 | TASK [ensure-podman : Validate podman engine] 2025-10-21 00:24:37.555359 | controller | skipping: Conditional result was False 2025-10-21 00:24:37.570562 | 2025-10-21 00:24:37.570778 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-21 00:24:37.597881 | controller | skipping: Conditional result was False 2025-10-21 00:24:37.628165 | 2025-10-21 00:24:37.628306 | TASK [Ensure python3.8 is present] 2025-10-21 00:24:37.653594 | controller | skipping: Conditional result was False 2025-10-21 00:24:37.668645 | 2025-10-21 00:24:37.668826 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-21 00:24:37.694863 | controller | ok 2025-10-21 00:24:37.728973 | 2025-10-21 00:24:37.729120 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-21 00:24:40.543595 | controller | ok: Nothing to do 2025-10-21 00:24:40.550395 | 2025-10-21 00:24:40.550512 | TASK [our-ensure-python : Also install python3-devel] 2025-10-21 00:24:53.482126 | controller | changed 2025-10-21 00:24:53.493961 | 2025-10-21 00:24:53.494061 | TASK [Run ensure-virtualenv role] 2025-10-21 00:24:53.514056 | controller | ok 2025-10-21 00:24:53.537629 | 2025-10-21 00:24:53.537765 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-21 00:24:54.282852 | controller | /usr/bin/virtualenv 2025-10-21 00:24:54.420026 | controller | ok: Runtime: 0:00:00.004425 2025-10-21 00:24:54.435035 | 2025-10-21 00:24:54.435151 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-21 00:24:54.460291 | controller | skipping: Conditional result was False 2025-10-21 00:24:54.460597 | controller | ok: All items complete 2025-10-21 00:24:54.460636 | 2025-10-21 00:24:54.480241 | 2025-10-21 00:24:54.480375 | TASK [Find the full path of the Python interpreter] 2025-10-21 00:24:55.037680 | controller | /usr/bin/python3 2025-10-21 00:24:55.348007 | controller | ok 2025-10-21 00:24:55.355092 | 2025-10-21 00:24:55.355215 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-21 00:24:56.851162 | controller | created virtual environment CPython3.11.0.final.0-64 in 715ms 2025-10-21 00:24:56.896060 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-21 00:24:56.896114 | 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-21 00:24:56.896128 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-21 00:24:56.896148 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-21 00:24:57.214343 | controller | changed 2025-10-21 00:24:57.230083 | 2025-10-21 00:24:57.230229 | TASK [Set selinux package] 2025-10-21 00:24:57.270550 | controller | ok 2025-10-21 00:24:57.282832 | 2025-10-21 00:24:57.282970 | TASK [Set selinux package (Fedora)] 2025-10-21 00:24:57.319295 | controller | ok 2025-10-21 00:24:57.334426 | 2025-10-21 00:24:57.334580 | TASK [Install selinux into virtualenv] 2025-10-21 00:24:59.903058 | controller | Collecting selinux-please-lie-to-me 2025-10-21 00:24:59.962245 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-21 00:25:00.418150 | controller | Collecting setuptools<50.0.0 2025-10-21 00:25:00.423735 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-21 00:25:00.478001 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 17.2 MB/s eta 0:00:00 2025-10-21 00:25:00.601290 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-21 00:25:00.602083 | controller | Attempting uninstall: setuptools 2025-10-21 00:25:00.606577 | controller | Found existing installation: setuptools 62.6.0 2025-10-21 00:25:00.698372 | controller | Uninstalling setuptools-62.6.0: 2025-10-21 00:25:00.710258 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-21 00:25:01.317124 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-21 00:25:01.492325 | controller | 2025-10-21 00:25:01.701977 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-21 00:25:01.702017 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-21 00:25:02.202845 | controller | ok: Runtime: 0:00:03.638607 2025-10-21 00:25:02.213468 | 2025-10-21 00:25:02.213606 | TASK [Install pytest-forked into virtualenv] 2025-10-21 00:25:03.524630 | controller | Collecting pytest-forked 2025-10-21 00:25:03.576796 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-21 00:25:03.625912 | controller | Collecting py 2025-10-21 00:25:03.629695 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-21 00:25:03.657423 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.7 MB/s eta 0:00:00 2025-10-21 00:25:03.801606 | controller | Collecting pytest>=3.10 2025-10-21 00:25:03.805550 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-21 00:25:03.823932 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 23.9 MB/s eta 0:00:00 2025-10-21 00:25:03.870009 | controller | Collecting iniconfig>=1 2025-10-21 00:25:03.874080 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-21 00:25:03.930386 | controller | Collecting packaging>=20 2025-10-21 00:25:03.934557 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-21 00:25:03.943064 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.0 MB/s eta 0:00:00 2025-10-21 00:25:03.985105 | controller | Collecting pluggy<2,>=1.5 2025-10-21 00:25:03.988827 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-21 00:25:04.050883 | controller | Collecting pygments>=2.7.2 2025-10-21 00:25:04.056296 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-21 00:25:04.081395 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 58.9 MB/s eta 0:00:00 2025-10-21 00:25:04.173567 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-21 00:25:06.014467 | controller | Successfully installed iniconfig-2.3.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-21 00:25:06.037924 | controller | 2025-10-21 00:25:06.238191 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-21 00:25:06.238245 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-21 00:25:06.615905 | controller | ok: Runtime: 0:00:03.292338 2025-10-21 00:25:06.622298 | 2025-10-21 00:25:06.622384 | TASK [Update pip] 2025-10-21 00:25:07.836413 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-21 00:25:08.049946 | controller | Collecting pip 2025-10-21 00:25:08.099522 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-21 00:25:08.157745 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 32.9 MB/s eta 0:00:00 2025-10-21 00:25:08.257091 | controller | Installing collected packages: pip 2025-10-21 00:25:08.258915 | controller | Attempting uninstall: pip 2025-10-21 00:25:08.262489 | controller | Found existing installation: pip 22.2.2 2025-10-21 00:25:08.520927 | controller | Uninstalling pip-22.2.2: 2025-10-21 00:25:08.563540 | controller | Successfully uninstalled pip-22.2.2 2025-10-21 00:25:09.968757 | controller | Successfully installed pip-25.2 2025-10-21 00:25:10.485014 | controller | ok: Runtime: 0:00:02.801097 2025-10-21 00:25:10.494097 | 2025-10-21 00:25:10.494223 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-21 00:25:11.290486 | controller | changed 2025-10-21 00:25:11.297055 | 2025-10-21 00:25:11.297178 | TASK [Install ansible into virtualenv] 2025-10-21 00:25:12.328998 | controller | Processing ./src/github.com/ansible/ansible 2025-10-21 00:25:12.333902 | controller | Installing build dependencies: started 2025-10-21 00:25:13.758992 | controller | Installing build dependencies: finished with status 'done' 2025-10-21 00:25:15.247464 | controller | Getting requirements to build wheel: started 2025-10-21 00:25:15.247524 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-21 00:25:15.249001 | controller | Preparing metadata (pyproject.toml): started 2025-10-21 00:25:16.006647 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-21 00:25:16.008615 | 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-21 00:25:16.010488 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-21 00:25:16.669639 | controller | ERROR 2025-10-21 00:25:16.669970 | controller | { 2025-10-21 00:25:16.670051 | controller | "delta": "0:00:04.375743", 2025-10-21 00:25:16.670105 | controller | "end": "2025-10-21 00:25:16.228691", 2025-10-21 00:25:16.670160 | controller | "msg": "non-zero return code", 2025-10-21 00:25:16.670232 | controller | "rc": 1, 2025-10-21 00:25:16.670275 | controller | "start": "2025-10-21 00:25:11.852948" 2025-10-21 00:25:16.670311 | controller | } failure 2025-10-21 00:25:16.673896 | 2025-10-21 00:25:16.674058 | PLAY RECAP 2025-10-21 00:25:16.674153 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-21 00:25:16.674203 | 2025-10-21 00:25:16.810588 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-21 00:25:16.811861 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-21 00:25:17.437060 | 2025-10-21 00:25:17.437175 | PLAY [all] 2025-10-21 00:25:17.459371 | 2025-10-21 00:25:17.459491 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-21 00:25:19.292852 | controller | changed: non-zero return code 2025-10-21 00:25:19.309411 | 2025-10-21 00:25:19.309836 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-21 00:25:19.326375 | controller | skipping: Conditional result was False 2025-10-21 00:25:19.337180 | 2025-10-21 00:25:19.337342 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-21 00:25:19.366879 | 2025-10-21 00:25:19.367079 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-21 00:25:19.391908 | 2025-10-21 00:25:19.392094 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-21 00:25:19.407888 | controller | skipping: Conditional result was False 2025-10-21 00:25:19.417416 | 2025-10-21 00:25:19.417528 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-21 00:25:19.442758 | 2025-10-21 00:25:19.442954 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-21 00:25:19.458600 | controller | skipping: Conditional result was False 2025-10-21 00:25:19.468451 | 2025-10-21 00:25:19.468573 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-21 00:25:19.484240 | controller | skipping: Conditional result was False 2025-10-21 00:25:19.493253 | 2025-10-21 00:25:19.493478 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-21 00:25:19.519024 | controller | skipping: Conditional result was False 2025-10-21 00:25:19.557358 | 2025-10-21 00:25:19.557468 | PLAY RECAP 2025-10-21 00:25:19.557525 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-21 00:25:19.557553 | 2025-10-21 00:25:19.668975 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-21 00:25:19.669881 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-21 00:25:20.334575 | 2025-10-21 00:25:20.334716 | PLAY [all:!appliance*] 2025-10-21 00:25:20.358155 | 2025-10-21 00:25:20.358280 | TASK [unregister the node] 2025-10-21 00:25:20.713066 | controller | skipping: Conditional result was False 2025-10-21 00:25:20.720082 | 2025-10-21 00:25:20.720198 | TASK [include_role : fetch-output] 2025-10-21 00:25:20.750845 | controller | ok 2025-10-21 00:25:20.772595 | 2025-10-21 00:25:20.772754 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-21 00:25:20.818388 | controller | skipping: Conditional result was False 2025-10-21 00:25:20.828760 | 2025-10-21 00:25:20.828975 | TASK [fetch-output : Set log path for single node] 2025-10-21 00:25:20.877439 | controller | ok 2025-10-21 00:25:20.887323 | 2025-10-21 00:25:20.887541 | LOOP [fetch-output : Ensure local output dirs] 2025-10-21 00:25:21.313284 | controller -> localhost | ok: "/var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/work/logs" 2025-10-21 00:25:21.542723 | controller -> localhost | changed: "/var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/work/artifacts" 2025-10-21 00:25:21.769302 | controller -> localhost | changed: "/var/lib/zuul/builds/0f63257d49374945be95b9eb2b8f5fc2/work/docs" 2025-10-21 00:25:21.790013 | 2025-10-21 00:25:21.790163 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-21 00:25:24.008164 | controller | changed: 2025-10-21 00:25:24.008372 | controller | .d..t...... ./ 2025-10-21 00:25:24.008408 | controller | cd+++++++++ controller/ 2025-10-21 00:25:24.008448 | controller | changed: All items complete 2025-10-21 00:25:24.008473 | 2025-10-21 00:25:26.066729 | controller | changed: .d..t...... ./ 2025-10-21 00:25:28.106569 | controller | changed: .d..t...... ./ 2025-10-21 00:25:28.141221 | 2025-10-21 00:25:28.141411 | TASK [include_role : fetch-output-openshift] 2025-10-21 00:25:28.168617 | controller | skipping: Conditional result was False 2025-10-21 00:25:28.184232 | 2025-10-21 00:25:28.184721 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-21 00:25:28.224225 | controller | skipping: Conditional result was False 2025-10-21 00:25:28.237850 | controller | skipping: Conditional result was False 2025-10-21 00:25:28.284937 | 2025-10-21 00:25:28.285050 | PLAY [localhost] 2025-10-21 00:25:28.298324 | 2025-10-21 00:25:28.298439 | TASK [Run Zuul manifest role] 2025-10-21 00:25:28.319502 | localhost | ok 2025-10-21 00:25:28.336519 | 2025-10-21 00:25:28.336604 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-21 00:25:28.722536 | localhost | changed 2025-10-21 00:25:28.728020 | 2025-10-21 00:25:28.728093 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-21 00:25:28.756185 | localhost | ok 2025-10-21 00:25:28.764621 | 2025-10-21 00:25:28.764726 | TASK [Set zuul-log-path fact] 2025-10-21 00:25:28.784389 | localhost | ok 2025-10-21 00:25:28.833068 | 2025-10-21 00:25:28.833184 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-21 00:25:28.871203 | localhost | ok 2025-10-21 00:25:28.878981 | 2025-10-21 00:25:28.879059 | LOOP [Run upload-logs-swift role] 2025-10-21 00:25:28.902541 | localhost | Output suppressed because no_log was given 2025-10-21 00:25:28.927143 | 2025-10-21 00:25:28.927241 | TASK [Set zuul-log-path fact] 2025-10-21 00:25:28.951023 | localhost | skipping: Conditional result was False 2025-10-21 00:25:28.956885 | 2025-10-21 00:25:28.956959 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-21 00:25:29.340129 | localhost -> localhost | ok: Runtime: 0:00:00.006241 2025-10-21 00:25:29.345441 | 2025-10-21 00:25:29.345504 | TASK [upload-logs-swift : Upload logs to swift]