2025-10-22 00:12:14.429975 | Job console starting... 2025-10-22 00:12:14.440525 | Updating repositories 2025-10-22 00:12:14.539494 | Preparing job workspace 2025-10-22 00:12:18.159651 | Running Ansible setup... 2025-10-22 00:12:24.391652 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-22 00:12:25.086300 | 2025-10-22 00:12:25.086450 | PLAY [localhost] 2025-10-22 00:12:25.100033 | 2025-10-22 00:12:25.100249 | TASK [Gathering Facts] 2025-10-22 00:12:26.219469 | localhost | ok 2025-10-22 00:12:26.237096 | 2025-10-22 00:12:26.237229 | TASK [Setup log path fact] 2025-10-22 00:12:26.268426 | localhost | ok 2025-10-22 00:12:26.289879 | 2025-10-22 00:12:26.289995 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-22 00:12:26.329597 | localhost | ok 2025-10-22 00:12:26.342452 | 2025-10-22 00:12:26.342748 | TASK [emit-job-header : Print job information] 2025-10-22 00:12:26.385775 | # Job Information 2025-10-22 00:12:26.385922 | Ansible Version: 2.15.12 2025-10-22 00:12:26.385955 | Job: ansible-test-sanity-docker-devel 2025-10-22 00:12:26.385977 | Pipeline: periodic 2025-10-22 00:12:26.385997 | Executor: ze01.softwarefactory-project.io 2025-10-22 00:12:26.386042 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-22 00:12:26.386071 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/3ed/ansible/3ed9e18f39ca420a8040331a1abf7bc2/ 2025-10-22 00:12:26.386093 | Event ID: 29cce05ecf284232acebc18c8d35e894 2025-10-22 00:12:26.395209 | 2025-10-22 00:12:26.395305 | LOOP [emit-job-header : Print node information] 2025-10-22 00:12:26.603123 | localhost | ok: 2025-10-22 00:12:26.603293 | localhost | # Node Information 2025-10-22 00:12:26.603331 | localhost | Inventory Hostname: controller 2025-10-22 00:12:26.603352 | localhost | Hostname: ip-172-16-246-247 2025-10-22 00:12:26.603371 | localhost | Username: zuul-worker 2025-10-22 00:12:26.603392 | localhost | Distro: Fedora 37 2025-10-22 00:12:26.603412 | localhost | Provider: ansible-us-east-2 2025-10-22 00:12:26.603430 | localhost | Region: us-east-2 2025-10-22 00:12:26.603447 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-22 00:12:26.603463 | localhost | Product Name: t3.small 2025-10-22 00:12:26.603480 | localhost | Interface IP: 18.188.166.225 2025-10-22 00:12:26.623930 | 2025-10-22 00:12:26.624107 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-22 00:12:27.122420 | localhost -> localhost | changed 2025-10-22 00:12:27.131118 | 2025-10-22 00:12:27.132557 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-22 00:12:28.124866 | localhost -> localhost | changed 2025-10-22 00:12:28.148894 | 2025-10-22 00:12:28.148996 | PLAY [all:!appliance*] 2025-10-22 00:12:28.166351 | 2025-10-22 00:12:28.166489 | TASK [include_role : start-zuul-console] 2025-10-22 00:12:28.189504 | controller | ok 2025-10-22 00:12:28.215247 | 2025-10-22 00:12:28.215417 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-22 00:12:28.916873 | controller | ok 2025-10-22 00:12:28.934461 | 2025-10-22 00:12:28.934573 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-22 00:12:30.399888 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-22 00:12:30.406956 | 2025-10-22 00:12:30.407064 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-22 00:12:30.547986 | controller | skipping: Conditional result was False 2025-10-22 00:12:30.562992 | 2025-10-22 00:12:30.563288 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-22 00:12:30.601441 | controller | skipping: Conditional result was False 2025-10-22 00:12:30.615035 | 2025-10-22 00:12:30.615189 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-22 00:12:30.641749 | controller | skipping: Conditional result was False 2025-10-22 00:12:30.650760 | 2025-10-22 00:12:30.650882 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-22 00:12:30.685925 | controller | skipping: Conditional result was False 2025-10-22 00:12:30.700616 | 2025-10-22 00:12:30.700778 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-22 00:12:30.729372 | controller | skipping: Conditional result was False 2025-10-22 00:12:30.742812 | 2025-10-22 00:12:30.743093 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-22 00:12:30.768822 | controller | skipping: Conditional result was False 2025-10-22 00:12:30.794912 | 2025-10-22 00:12:30.795205 | TASK [Disable Fedora Modular] 2025-10-22 00:12:31.510768 | controller | changed 2025-10-22 00:12:31.517791 | 2025-10-22 00:12:31.517886 | TASK [Enable EPEL] 2025-10-22 00:12:31.542865 | controller | skipping: Conditional result was False 2025-10-22 00:12:31.551247 | 2025-10-22 00:12:31.551368 | TASK [Register the RHEL node] 2025-10-22 00:12:31.709879 | 2025-10-22 00:12:31.710047 | TASK [Show the subscription-manager status] 2025-10-22 00:12:31.910863 | controller | skipping: Conditional result was False 2025-10-22 00:12:31.921442 | 2025-10-22 00:12:31.921558 | TASK [Enable EPEL on RHEL] 2025-10-22 00:12:32.088445 | controller | skipping: Conditional result was False 2025-10-22 00:12:32.098801 | 2025-10-22 00:12:32.098981 | TASK [Install git and tox] 2025-10-22 00:14:08.711110 | controller | changed 2025-10-22 00:14:08.717398 | 2025-10-22 00:14:08.717478 | TASK [include_role : prepare-workspace] 2025-10-22 00:14:08.738516 | controller | ok 2025-10-22 00:14:08.768921 | 2025-10-22 00:14:08.769115 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-22 00:14:09.310103 | controller | ok 2025-10-22 00:14:09.325617 | 2025-10-22 00:14:09.325798 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-22 00:14:23.140526 | controller | Output suppressed because no_log was given 2025-10-22 00:14:23.154324 | 2025-10-22 00:14:23.154417 | TASK [include_role : prepare-workspace-openshift] 2025-10-22 00:14:23.171175 | controller | skipping: Conditional result was False 2025-10-22 00:14:23.199173 | 2025-10-22 00:14:23.199283 | PLAY [all:!appliance] 2025-10-22 00:14:23.251746 | 2025-10-22 00:14:23.252238 | TASK [Run add-build-sshkey role (RSA)] 2025-10-22 00:14:23.283081 | controller | ok 2025-10-22 00:14:23.300500 | 2025-10-22 00:14:23.300635 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-22 00:14:23.600864 | controller -> localhost | ok 2025-10-22 00:14:23.608656 | 2025-10-22 00:14:23.608759 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-22 00:14:23.652092 | controller | ok 2025-10-22 00:14:23.670471 | controller | included: /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-22 00:14:23.680841 | 2025-10-22 00:14:23.681004 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-22 00:14:24.220812 | controller -> localhost | Generating public/private rsa key pair. 2025-10-22 00:14:24.221088 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/work/3ed9e18f39ca420a8040331a1abf7bc2_id_rsa. 2025-10-22 00:14:24.221131 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/work/3ed9e18f39ca420a8040331a1abf7bc2_id_rsa.pub. 2025-10-22 00:14:24.221161 | controller -> localhost | The key fingerprint is: 2025-10-22 00:14:24.221188 | controller -> localhost | SHA256:69sbGbZWsBGPCLrYS7ycREgTZGSBWf4YvCsRQuXbsvw zuul-build-sshkey 2025-10-22 00:14:24.221209 | controller -> localhost | The key's randomart image is: 2025-10-22 00:14:24.221228 | controller -> localhost | +---[RSA 2048]----+ 2025-10-22 00:14:24.221246 | controller -> localhost | | B%+ . . | 2025-10-22 00:14:24.221265 | controller -> localhost | |+*.o . . . + | 2025-10-22 00:14:24.221285 | controller -> localhost | |o =.o . + . | 2025-10-22 00:14:24.221305 | controller -> localhost | |.. Xo. + | 2025-10-22 00:14:24.221322 | controller -> localhost | |. +oB. S + . | 2025-10-22 00:14:24.221349 | controller -> localhost | | ..=o+ o = | 2025-10-22 00:14:24.221373 | controller -> localhost | |. .o= . = | 2025-10-22 00:14:24.221393 | controller -> localhost | | . . . o . | 2025-10-22 00:14:24.221410 | controller -> localhost | | E o.o. | 2025-10-22 00:14:24.221433 | controller -> localhost | +----[SHA256]-----+ 2025-10-22 00:14:24.221495 | controller -> localhost | ok: Runtime: 0:00:00.095012 2025-10-22 00:14:24.228070 | 2025-10-22 00:14:24.228142 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-22 00:14:24.266454 | controller | ok 2025-10-22 00:14:24.277034 | controller | included: /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-22 00:14:24.285847 | 2025-10-22 00:14:24.285910 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-22 00:14:24.310162 | controller | skipping: Conditional result was False 2025-10-22 00:14:24.317214 | 2025-10-22 00:14:24.317285 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-22 00:14:25.124503 | controller | changed 2025-10-22 00:14:25.130753 | 2025-10-22 00:14:25.130827 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-22 00:14:25.531620 | controller | ok 2025-10-22 00:14:25.537157 | 2025-10-22 00:14:25.537235 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-22 00:14:27.017359 | controller | changed 2025-10-22 00:14:27.030908 | 2025-10-22 00:14:27.031129 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-22 00:14:28.475445 | controller | changed 2025-10-22 00:14:28.482153 | 2025-10-22 00:14:28.482272 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-22 00:14:28.507173 | controller | skipping: Conditional result was False 2025-10-22 00:14:28.514625 | 2025-10-22 00:14:28.514739 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-22 00:14:28.919117 | controller -> localhost | changed 2025-10-22 00:14:28.960622 | 2025-10-22 00:14:28.960807 | TASK [add-build-sshkey : Add back temp key] 2025-10-22 00:14:29.260684 | controller -> localhost | Identity added: /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/work/3ed9e18f39ca420a8040331a1abf7bc2_id_rsa (zuul-build-sshkey) 2025-10-22 00:14:29.260911 | controller -> localhost | ok: Runtime: 0:00:00.007545 2025-10-22 00:14:29.267367 | 2025-10-22 00:14:29.267435 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-22 00:14:29.828850 | controller | ok 2025-10-22 00:14:29.834281 | 2025-10-22 00:14:29.834355 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-22 00:14:29.858544 | controller | skipping: Conditional result was False 2025-10-22 00:14:29.871432 | 2025-10-22 00:14:29.871581 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-22 00:14:29.901560 | controller | ok 2025-10-22 00:14:29.918340 | 2025-10-22 00:14:29.918455 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-22 00:14:30.188742 | controller -> localhost | ok 2025-10-22 00:14:30.195170 | 2025-10-22 00:14:30.195242 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-22 00:14:30.217547 | controller | ok 2025-10-22 00:14:30.235842 | controller | included: /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-22 00:14:30.242120 | 2025-10-22 00:14:30.242239 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-22 00:14:30.542686 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-22 00:14:30.542878 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/work/3ed9e18f39ca420a8040331a1abf7bc2_id_ecdsa. 2025-10-22 00:14:30.542906 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/work/3ed9e18f39ca420a8040331a1abf7bc2_id_ecdsa.pub. 2025-10-22 00:14:30.542939 | controller -> localhost | The key fingerprint is: 2025-10-22 00:14:30.542960 | controller -> localhost | SHA256:/MVXTRzmc+/hT4lsOyl+BSlS9zG6YnfG0bzT0oNm5GQ zuul-build-sshkey 2025-10-22 00:14:30.542981 | controller -> localhost | The key's randomart image is: 2025-10-22 00:14:30.543000 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-22 00:14:30.543042 | controller -> localhost | | +o| 2025-10-22 00:14:30.543063 | controller -> localhost | | . .o+o| 2025-10-22 00:14:30.543082 | controller -> localhost | | . . ++B| 2025-10-22 00:14:30.543099 | controller -> localhost | | . . o E +*| 2025-10-22 00:14:30.543116 | controller -> localhost | | S . O *o=| 2025-10-22 00:14:30.543133 | controller -> localhost | | . +.O+X=| 2025-10-22 00:14:30.543151 | controller -> localhost | | o =+=+=| 2025-10-22 00:14:30.543168 | controller -> localhost | | ..+...| 2025-10-22 00:14:30.543185 | controller -> localhost | | ..o.. .| 2025-10-22 00:14:30.543202 | controller -> localhost | +----[SHA256]-----+ 2025-10-22 00:14:30.543248 | controller -> localhost | ok: Runtime: 0:00:00.008096 2025-10-22 00:14:30.549980 | 2025-10-22 00:14:30.550085 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-22 00:14:30.573911 | controller | ok 2025-10-22 00:14:30.586511 | controller | included: /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-22 00:14:30.595892 | 2025-10-22 00:14:30.595982 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-22 00:14:30.620098 | controller | skipping: Conditional result was False 2025-10-22 00:14:30.628889 | 2025-10-22 00:14:30.629049 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-22 00:14:31.131182 | controller | changed 2025-10-22 00:14:31.139673 | 2025-10-22 00:14:31.139786 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-22 00:14:31.508129 | controller | ok 2025-10-22 00:14:31.523294 | 2025-10-22 00:14:31.523445 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-22 00:14:32.833562 | controller | changed 2025-10-22 00:14:32.840459 | 2025-10-22 00:14:32.840557 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-22 00:14:34.161278 | controller | changed 2025-10-22 00:14:34.174849 | 2025-10-22 00:14:34.175056 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-22 00:14:34.212734 | controller | skipping: Conditional result was False 2025-10-22 00:14:34.228108 | 2025-10-22 00:14:34.228305 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-22 00:14:34.508408 | controller -> localhost | changed 2025-10-22 00:14:34.523736 | 2025-10-22 00:14:34.524104 | TASK [add-build-sshkey : Add back temp key] 2025-10-22 00:14:34.837679 | controller -> localhost | Identity added: /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/work/3ed9e18f39ca420a8040331a1abf7bc2_id_ecdsa (zuul-build-sshkey) 2025-10-22 00:14:34.837958 | controller -> localhost | ok: Runtime: 0:00:00.013435 2025-10-22 00:14:34.848028 | 2025-10-22 00:14:34.848148 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-22 00:14:35.282730 | controller | ok 2025-10-22 00:14:35.288802 | 2025-10-22 00:14:35.288929 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-22 00:14:35.313451 | controller | skipping: Conditional result was False 2025-10-22 00:14:35.327932 | 2025-10-22 00:14:35.328106 | TASK [include_role : remove-zuul-sshkey] 2025-10-22 00:14:35.344123 | controller | skipping: Conditional result was False 2025-10-22 00:14:35.353761 | 2025-10-22 00:14:35.353908 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-22 00:14:35.697818 | controller | ok: "logs" 2025-10-22 00:14:35.698148 | controller | ok: All items complete 2025-10-22 00:14:35.698206 | 2025-10-22 00:14:35.998780 | controller | ok: "artifacts" 2025-10-22 00:14:36.320897 | controller | ok: "docs" 2025-10-22 00:14:36.340110 | 2025-10-22 00:14:36.340322 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-22 00:14:36.719362 | controller | changed: "logs" 2025-10-22 00:14:37.128048 | controller | changed: "artifacts" 2025-10-22 00:14:37.457346 | controller | changed: "docs" 2025-10-22 00:14:37.525327 | 2025-10-22 00:14:37.525444 | PLAY RECAP 2025-10-22 00:14:37.525505 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-22 00:14:37.525544 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-22 00:14:37.525572 | 2025-10-22 00:14:37.665183 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-22 00:14:37.666059 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-22 00:14:38.288995 | 2025-10-22 00:14:38.289180 | PLAY [all] 2025-10-22 00:14:38.319120 | 2025-10-22 00:14:38.319289 | TASK [Install binary dependencies] 2025-10-22 00:14:38.376172 | controller | ok 2025-10-22 00:14:38.395518 | 2025-10-22 00:14:38.395644 | TASK [bindep : Include find tasks] 2025-10-22 00:14:38.425303 | controller | ok 2025-10-22 00:14:38.433196 | controller | included: /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-22 00:14:38.439161 | 2025-10-22 00:14:38.439227 | TASK [bindep : Look for bindep.txt] 2025-10-22 00:14:39.021470 | controller | ok 2025-10-22 00:14:39.028543 | 2025-10-22 00:14:39.028639 | TASK [bindep : Define bindep_file fact] 2025-10-22 00:14:39.054460 | controller | skipping: Conditional result was False 2025-10-22 00:14:39.061624 | 2025-10-22 00:14:39.061735 | TASK [bindep : Look for other-requirements.txt] 2025-10-22 00:14:39.412481 | controller | ok 2025-10-22 00:14:39.426321 | 2025-10-22 00:14:39.426727 | TASK [bindep : Define bindep_file fact] 2025-10-22 00:14:39.466943 | controller | skipping: Conditional result was False 2025-10-22 00:14:39.480336 | 2025-10-22 00:14:39.480495 | TASK [bindep : Look for bindep fallback file] 2025-10-22 00:14:39.527787 | controller | skipping: Conditional result was False 2025-10-22 00:14:39.541329 | 2025-10-22 00:14:39.541487 | TASK [bindep : Define bindep_file fact] 2025-10-22 00:14:39.569261 | controller | skipping: Conditional result was False 2025-10-22 00:14:39.582738 | 2025-10-22 00:14:39.582885 | TASK [bindep : Include bindep tasks] 2025-10-22 00:14:39.620375 | controller | skipping: Conditional result was False 2025-10-22 00:14:39.637778 | 2025-10-22 00:14:39.637964 | TASK [bindep : Include install tasks] 2025-10-22 00:14:39.676566 | controller | skipping: Conditional result was False 2025-10-22 00:14:39.690078 | 2025-10-22 00:14:39.690262 | LOOP [bindep : Include package tasks] 2025-10-22 00:14:39.761339 | 2025-10-22 00:14:39.761658 | TASK [Run test-setup role] 2025-10-22 00:14:39.785481 | controller | ok 2025-10-22 00:14:39.810565 | 2025-10-22 00:14:39.810699 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-22 00:14:40.149131 | controller | ok 2025-10-22 00:14:40.156675 | 2025-10-22 00:14:40.156778 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-22 00:14:40.296612 | controller | skipping: Conditional result was False 2025-10-22 00:14:40.332508 | 2025-10-22 00:14:40.332667 | PLAY RECAP 2025-10-22 00:14:40.332730 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-22 00:14:40.332762 | 2025-10-22 00:14:40.444223 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-22 00:14:40.445086 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-22 00:14:41.083527 | 2025-10-22 00:14:41.083680 | PLAY [controller] 2025-10-22 00:14:41.104086 | 2025-10-22 00:14:41.104208 | TASK [Create the /root directory] 2025-10-22 00:14:41.822118 | controller | ok 2025-10-22 00:14:41.833084 | 2025-10-22 00:14:41.833255 | TASK [Install glibc-langpack-en] 2025-10-22 00:14:49.972989 | controller | ok: Nothing to do 2025-10-22 00:14:49.978718 | 2025-10-22 00:14:49.978812 | TASK [Ensure controller directory exists] 2025-10-22 00:14:50.441709 | controller | changed 2025-10-22 00:14:50.450314 | 2025-10-22 00:14:50.450448 | TASK [Install container runtime] 2025-10-22 00:14:50.517474 | controller | ok 2025-10-22 00:14:50.566049 | 2025-10-22 00:14:50.566294 | LOOP [ensure-podman : Find distribution installation] 2025-10-22 00:14:50.604476 | controller | ok: "/var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-22 00:14:50.614369 | controller | included: /var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-22 00:14:50.622115 | 2025-10-22 00:14:50.622216 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-22 00:16:18.325560 | controller | changed 2025-10-22 00:16:18.343109 | 2025-10-22 00:16:18.343258 | TASK [ensure-podman : Fetch podman version] 2025-10-22 00:16:19.089672 | controller | Client: Podman Engine 2025-10-22 00:16:19.089784 | controller | Version: 4.6.2 2025-10-22 00:16:19.089832 | controller | API Version: 4.6.2 2025-10-22 00:16:19.089875 | controller | Go Version: go1.19.12 2025-10-22 00:16:19.089928 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-22 00:16:19.089966 | controller | OS/Arch: linux/amd64 2025-10-22 00:16:19.510689 | controller | ok: Runtime: 0:00:00.227975 2025-10-22 00:16:19.528525 | 2025-10-22 00:16:19.528745 | TASK [ensure-podman : Print podman version installed] 2025-10-22 00:16:19.570214 | Podman version: Client: Podman Engine 2025-10-22 00:16:19.570475 | Version: 4.6.2 2025-10-22 00:16:19.570554 | API Version: 4.6.2 2025-10-22 00:16:19.570606 | Go Version: go1.19.12 2025-10-22 00:16:19.570648 | Built: Mon Aug 28 19:38:31 2023 2025-10-22 00:16:19.570688 | OS/Arch: linux/amd64 2025-10-22 00:16:19.582621 | 2025-10-22 00:16:19.582761 | TASK [ensure-podman : Validate podman engine] 2025-10-22 00:16:19.738125 | controller | skipping: Conditional result was False 2025-10-22 00:16:19.753641 | 2025-10-22 00:16:19.753801 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-22 00:16:19.771351 | controller | skipping: Conditional result was False 2025-10-22 00:16:19.788031 | 2025-10-22 00:16:19.788125 | TASK [Ensure python3.8 is present] 2025-10-22 00:16:19.804206 | controller | skipping: Conditional result was False 2025-10-22 00:16:19.811915 | 2025-10-22 00:16:19.812001 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-22 00:16:19.833271 | controller | ok 2025-10-22 00:16:19.860623 | 2025-10-22 00:16:19.860796 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-22 00:16:23.608970 | controller | ok: Nothing to do 2025-10-22 00:16:23.620667 | 2025-10-22 00:16:23.620807 | TASK [our-ensure-python : Also install python3-devel] 2025-10-22 00:16:37.109894 | controller | changed 2025-10-22 00:16:37.134528 | 2025-10-22 00:16:37.134685 | TASK [Run ensure-virtualenv role] 2025-10-22 00:16:37.158293 | controller | ok 2025-10-22 00:16:37.205509 | 2025-10-22 00:16:37.205700 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-22 00:16:37.667684 | controller | /usr/bin/virtualenv 2025-10-22 00:16:37.863514 | controller | ok: Runtime: 0:00:00.005367 2025-10-22 00:16:37.876551 | 2025-10-22 00:16:37.876754 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-22 00:16:37.900006 | controller | skipping: Conditional result was False 2025-10-22 00:16:37.900412 | controller | ok: All items complete 2025-10-22 00:16:37.900446 | 2025-10-22 00:16:37.928798 | 2025-10-22 00:16:37.928995 | TASK [Find the full path of the Python interpreter] 2025-10-22 00:16:38.457718 | controller | /usr/bin/python3 2025-10-22 00:16:38.623356 | controller | ok 2025-10-22 00:16:38.634213 | 2025-10-22 00:16:38.634383 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-22 00:16:40.045158 | controller | created virtual environment CPython3.11.0.final.0-64 in 767ms 2025-10-22 00:16:40.095017 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-22 00:16:40.095070 | 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-worker/.local/share/virtualenv) 2025-10-22 00:16:40.095087 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-22 00:16:40.095110 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-22 00:16:40.302134 | controller | changed 2025-10-22 00:16:40.333313 | 2025-10-22 00:16:40.333528 | TASK [Set selinux package] 2025-10-22 00:16:40.367898 | controller | ok 2025-10-22 00:16:40.376679 | 2025-10-22 00:16:40.376818 | TASK [Set selinux package (Fedora)] 2025-10-22 00:16:40.419236 | controller | ok 2025-10-22 00:16:40.424499 | 2025-10-22 00:16:40.424574 | TASK [Install selinux into virtualenv] 2025-10-22 00:16:43.035588 | controller | Collecting selinux-please-lie-to-me 2025-10-22 00:16:43.123442 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-22 00:16:43.654918 | controller | Collecting setuptools<50.0.0 2025-10-22 00:16:43.668859 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-22 00:16:43.801341 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.4 MB/s eta 0:00:00 2025-10-22 00:16:43.957941 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-22 00:16:43.958345 | controller | Attempting uninstall: setuptools 2025-10-22 00:16:43.963289 | controller | Found existing installation: setuptools 62.6.0 2025-10-22 00:16:44.076729 | controller | Uninstalling setuptools-62.6.0: 2025-10-22 00:16:44.092071 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-22 00:16:44.877936 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-22 00:16:45.132562 | controller | 2025-10-22 00:16:45.349691 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-22 00:16:45.349746 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-22 00:16:45.569680 | controller | ok: Runtime: 0:00:04.458881 2025-10-22 00:16:45.575441 | 2025-10-22 00:16:45.575516 | TASK [Install pytest-forked into virtualenv] 2025-10-22 00:16:46.791080 | controller | Collecting pytest-forked 2025-10-22 00:16:46.883488 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-22 00:16:47.005045 | controller | Collecting py 2025-10-22 00:16:47.019714 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-22 00:16:47.056908 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00 2025-10-22 00:16:47.233170 | controller | Collecting pytest>=3.10 2025-10-22 00:16:47.248367 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-22 00:16:47.316253 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.6 MB/s eta 0:00:00 2025-10-22 00:16:47.399957 | controller | Collecting iniconfig>=1 2025-10-22 00:16:47.461724 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-22 00:16:47.604366 | controller | Collecting packaging>=20 2025-10-22 00:16:47.617863 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-22 00:16:47.634554 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.3 MB/s eta 0:00:00 2025-10-22 00:16:47.748890 | controller | Collecting pluggy<2,>=1.5 2025-10-22 00:16:47.763566 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-22 00:16:47.933028 | controller | Collecting pygments>=2.7.2 2025-10-22 00:16:47.947114 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-22 00:16:48.083194 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.2 MB/s eta 0:00:00 2025-10-22 00:16:48.215204 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-22 00:16:50.469583 | 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-22 00:16:50.485783 | controller | 2025-10-22 00:16:50.680743 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-22 00:16:50.680796 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-22 00:16:50.783393 | controller | ok: Runtime: 0:00:04.627478 2025-10-22 00:16:50.789743 | 2025-10-22 00:16:50.789814 | TASK [Update pip] 2025-10-22 00:16:51.882708 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-22 00:16:52.157965 | controller | Collecting pip 2025-10-22 00:16:52.264339 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-22 00:16:52.464974 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.9 MB/s eta 0:00:00 2025-10-22 00:16:52.627546 | controller | Installing collected packages: pip 2025-10-22 00:16:52.628297 | controller | Attempting uninstall: pip 2025-10-22 00:16:52.639432 | controller | Found existing installation: pip 22.2.2 2025-10-22 00:16:52.963871 | controller | Uninstalling pip-22.2.2: 2025-10-22 00:16:53.003124 | controller | Successfully uninstalled pip-22.2.2 2025-10-22 00:16:54.751965 | controller | Successfully installed pip-25.2 2025-10-22 00:16:55.456067 | controller | ok: Runtime: 0:00:03.704623 2025-10-22 00:16:55.467841 | 2025-10-22 00:16:55.468010 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-22 00:16:55.993350 | controller | changed 2025-10-22 00:16:55.999636 | 2025-10-22 00:16:55.999747 | TASK [Install ansible into virtualenv] 2025-10-22 00:16:57.101986 | controller | Processing ./src/github.com/ansible/ansible 2025-10-22 00:16:57.109774 | controller | Installing build dependencies: started 2025-10-22 00:16:58.879243 | controller | Installing build dependencies: finished with status 'done' 2025-10-22 00:17:00.406976 | controller | Getting requirements to build wheel: started 2025-10-22 00:17:00.407039 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-22 00:17:01.337439 | controller | Preparing metadata (pyproject.toml): started 2025-10-22 00:17:01.337491 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-22 00:17:01.342321 | 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-22 00:17:01.347423 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-22 00:17:01.649588 | controller | ERROR 2025-10-22 00:17:01.649869 | controller | { 2025-10-22 00:17:01.649922 | controller | "delta": "0:00:05.026771", 2025-10-22 00:17:01.649960 | controller | "end": "2025-10-22 00:17:01.500190", 2025-10-22 00:17:01.649991 | controller | "msg": "non-zero return code", 2025-10-22 00:17:01.650125 | controller | "rc": 1, 2025-10-22 00:17:01.650167 | controller | "start": "2025-10-22 00:16:56.473419" 2025-10-22 00:17:01.650201 | controller | } failure 2025-10-22 00:17:01.652851 | 2025-10-22 00:17:01.652918 | PLAY RECAP 2025-10-22 00:17:01.652975 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-22 00:17:01.653004 | 2025-10-22 00:17:01.772586 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-22 00:17:01.773570 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-22 00:17:02.388777 | 2025-10-22 00:17:02.388901 | PLAY [all] 2025-10-22 00:17:02.411722 | 2025-10-22 00:17:02.411861 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-22 00:17:03.419256 | controller | changed: non-zero return code 2025-10-22 00:17:03.433202 | 2025-10-22 00:17:03.433550 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-22 00:17:03.462551 | controller | skipping: Conditional result was False 2025-10-22 00:17:03.480207 | 2025-10-22 00:17:03.480418 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-22 00:17:03.523809 | 2025-10-22 00:17:03.524126 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-22 00:17:03.564178 | 2025-10-22 00:17:03.564457 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-22 00:17:03.591377 | controller | skipping: Conditional result was False 2025-10-22 00:17:03.604886 | 2025-10-22 00:17:03.605111 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-22 00:17:03.656602 | 2025-10-22 00:17:03.656884 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-22 00:17:03.684190 | controller | skipping: Conditional result was False 2025-10-22 00:17:03.697509 | 2025-10-22 00:17:03.697709 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-22 00:17:03.724838 | controller | skipping: Conditional result was False 2025-10-22 00:17:03.738252 | 2025-10-22 00:17:03.738430 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-22 00:17:03.755746 | controller | skipping: Conditional result was False 2025-10-22 00:17:03.802490 | 2025-10-22 00:17:03.802616 | PLAY RECAP 2025-10-22 00:17:03.802680 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-22 00:17:03.802722 | 2025-10-22 00:17:03.911437 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-22 00:17:03.913675 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-22 00:17:04.593933 | 2025-10-22 00:17:04.594069 | PLAY [all:!appliance*] 2025-10-22 00:17:04.620124 | 2025-10-22 00:17:04.620271 | TASK [unregister the node] 2025-10-22 00:17:04.777739 | controller | skipping: Conditional result was False 2025-10-22 00:17:04.793363 | 2025-10-22 00:17:04.793561 | TASK [include_role : fetch-output] 2025-10-22 00:17:04.845956 | controller | ok 2025-10-22 00:17:04.883708 | 2025-10-22 00:17:04.883850 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-22 00:17:04.949689 | controller | skipping: Conditional result was False 2025-10-22 00:17:04.958589 | 2025-10-22 00:17:04.958701 | TASK [fetch-output : Set log path for single node] 2025-10-22 00:17:05.001488 | controller | ok 2025-10-22 00:17:05.008619 | 2025-10-22 00:17:05.008705 | LOOP [fetch-output : Ensure local output dirs] 2025-10-22 00:17:05.424418 | controller -> localhost | ok: "/var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/work/logs" 2025-10-22 00:17:05.654632 | controller -> localhost | changed: "/var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/work/artifacts" 2025-10-22 00:17:05.929282 | controller -> localhost | changed: "/var/lib/zuul/builds/3ed9e18f39ca420a8040331a1abf7bc2/work/docs" 2025-10-22 00:17:05.949601 | 2025-10-22 00:17:05.949802 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-22 00:17:07.333469 | controller | changed: 2025-10-22 00:17:07.333980 | controller | .d..t...... ./ 2025-10-22 00:17:07.334120 | controller | cd+++++++++ controller/ 2025-10-22 00:17:07.334219 | controller | changed: All items complete 2025-10-22 00:17:07.334280 | 2025-10-22 00:17:08.408248 | controller | changed: .d..t...... ./ 2025-10-22 00:17:09.505167 | controller | changed: .d..t...... ./ 2025-10-22 00:17:09.540926 | 2025-10-22 00:17:09.541091 | TASK [include_role : fetch-output-openshift] 2025-10-22 00:17:09.566297 | controller | skipping: Conditional result was False 2025-10-22 00:17:09.577429 | 2025-10-22 00:17:09.577556 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-22 00:17:09.614763 | controller | skipping: Conditional result was False 2025-10-22 00:17:09.625684 | controller | skipping: Conditional result was False 2025-10-22 00:17:09.675206 | 2025-10-22 00:17:09.675385 | PLAY [localhost] 2025-10-22 00:17:09.694840 | 2025-10-22 00:17:09.694964 | TASK [Run Zuul manifest role] 2025-10-22 00:17:09.717170 | localhost | ok 2025-10-22 00:17:09.737387 | 2025-10-22 00:17:09.737543 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-22 00:17:10.174519 | localhost | changed 2025-10-22 00:17:10.179742 | 2025-10-22 00:17:10.179831 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-22 00:17:10.219910 | localhost | ok 2025-10-22 00:17:10.231755 | 2025-10-22 00:17:10.231889 | TASK [Set zuul-log-path fact] 2025-10-22 00:17:10.253069 | localhost | ok 2025-10-22 00:17:10.271218 | 2025-10-22 00:17:10.271382 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-22 00:17:10.299895 | localhost | ok 2025-10-22 00:17:10.309448 | 2025-10-22 00:17:10.309554 | LOOP [Run upload-logs-swift role] 2025-10-22 00:17:10.333908 | localhost | Output suppressed because no_log was given 2025-10-22 00:17:10.359749 | 2025-10-22 00:17:10.359865 | TASK [Set zuul-log-path fact] 2025-10-22 00:17:10.383580 | localhost | skipping: Conditional result was False 2025-10-22 00:17:10.389129 | 2025-10-22 00:17:10.389241 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-22 00:17:10.854697 | localhost -> localhost | ok: Runtime: 0:00:00.005475 2025-10-22 00:17:10.866193 | 2025-10-22 00:17:10.866376 | TASK [upload-logs-swift : Upload logs to swift]