2025-10-30 00:17:58.511342 | Job console starting... 2025-10-30 00:17:58.527386 | Updating repositories 2025-10-30 00:17:58.688165 | Preparing job workspace 2025-10-30 00:18:03.499018 | Running Ansible setup... 2025-10-30 00:18:10.018899 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-30 00:18:10.670154 | 2025-10-30 00:18:10.670292 | PLAY [localhost] 2025-10-30 00:18:10.678721 | 2025-10-30 00:18:10.678794 | TASK [Gathering Facts] 2025-10-30 00:18:11.672331 | localhost | ok 2025-10-30 00:18:11.690706 | 2025-10-30 00:18:11.690846 | TASK [Setup log path fact] 2025-10-30 00:18:11.711792 | localhost | ok 2025-10-30 00:18:11.728891 | 2025-10-30 00:18:11.729055 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-30 00:18:11.768931 | localhost | ok 2025-10-30 00:18:11.777282 | 2025-10-30 00:18:11.777400 | TASK [emit-job-header : Print job information] 2025-10-30 00:18:11.831541 | # Job Information 2025-10-30 00:18:11.831851 | Ansible Version: 2.15.12 2025-10-30 00:18:11.831924 | Job: ansible-test-sanity-docker-devel 2025-10-30 00:18:11.831971 | Pipeline: periodic 2025-10-30 00:18:11.832011 | Executor: ze02.softwarefactory-project.io 2025-10-30 00:18:11.832050 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-30 00:18:11.832096 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/d83/ansible/d839c35b4d584f6397dfae1e9e90704f/ 2025-10-30 00:18:11.832138 | Event ID: 3d3b3e11113e4aa4883722e12166235f 2025-10-30 00:18:11.841120 | 2025-10-30 00:18:11.841343 | LOOP [emit-job-header : Print node information] 2025-10-30 00:18:11.946408 | localhost | ok: 2025-10-30 00:18:11.946652 | localhost | # Node Information 2025-10-30 00:18:11.946704 | localhost | Inventory Hostname: controller 2025-10-30 00:18:11.946725 | localhost | Hostname: ip-172-16-242-227 2025-10-30 00:18:11.946744 | localhost | Username: zuul-worker 2025-10-30 00:18:11.946764 | localhost | Distro: Fedora 37 2025-10-30 00:18:11.946781 | localhost | Provider: ansible-us-east-2 2025-10-30 00:18:11.946798 | localhost | Region: us-east-2 2025-10-30 00:18:11.946814 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-30 00:18:11.946830 | localhost | Product Name: t3.small 2025-10-30 00:18:11.946846 | localhost | Interface IP: 3.15.13.13 2025-10-30 00:18:11.966844 | 2025-10-30 00:18:11.967037 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-30 00:18:12.392484 | localhost -> localhost | changed 2025-10-30 00:18:12.397876 | 2025-10-30 00:18:12.397943 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-30 00:18:13.372188 | localhost -> localhost | changed 2025-10-30 00:18:13.394364 | 2025-10-30 00:18:13.394444 | PLAY [all:!appliance*] 2025-10-30 00:18:13.412744 | 2025-10-30 00:18:13.412825 | TASK [include_role : start-zuul-console] 2025-10-30 00:18:13.434649 | controller | ok 2025-10-30 00:18:13.450406 | 2025-10-30 00:18:13.450493 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-30 00:18:14.152789 | controller | ok 2025-10-30 00:18:14.175075 | 2025-10-30 00:18:14.175216 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-30 00:18:16.215370 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-30 00:18:16.231280 | 2025-10-30 00:18:16.231600 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-30 00:18:16.370144 | controller | skipping: Conditional result was False 2025-10-30 00:18:16.379071 | 2025-10-30 00:18:16.379325 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-30 00:18:16.414708 | controller | skipping: Conditional result was False 2025-10-30 00:18:16.429292 | 2025-10-30 00:18:16.429446 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-30 00:18:16.466104 | controller | skipping: Conditional result was False 2025-10-30 00:18:16.482395 | 2025-10-30 00:18:16.482594 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-30 00:18:16.511196 | controller | skipping: Conditional result was False 2025-10-30 00:18:16.528651 | 2025-10-30 00:18:16.528883 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-30 00:18:16.566061 | controller | skipping: Conditional result was False 2025-10-30 00:18:16.579431 | 2025-10-30 00:18:16.579611 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-30 00:18:16.616844 | controller | skipping: Conditional result was False 2025-10-30 00:18:16.649050 | 2025-10-30 00:18:16.649253 | TASK [Disable Fedora Modular] 2025-10-30 00:18:17.443792 | controller | changed 2025-10-30 00:18:17.457928 | 2025-10-30 00:18:17.458199 | TASK [Enable EPEL] 2025-10-30 00:18:17.486345 | controller | skipping: Conditional result was False 2025-10-30 00:18:17.501787 | 2025-10-30 00:18:17.501934 | TASK [Register the RHEL node] 2025-10-30 00:18:17.688015 | 2025-10-30 00:18:17.689106 | TASK [Show the subscription-manager status] 2025-10-30 00:18:17.894162 | controller | skipping: Conditional result was False 2025-10-30 00:18:17.901010 | 2025-10-30 00:18:17.901082 | TASK [Enable EPEL on RHEL] 2025-10-30 00:18:18.048980 | controller | skipping: Conditional result was False 2025-10-30 00:18:18.062068 | 2025-10-30 00:18:18.062208 | TASK [Install git and tox] 2025-10-30 00:19:52.749520 | controller | changed 2025-10-30 00:19:52.756747 | 2025-10-30 00:19:52.756819 | TASK [include_role : prepare-workspace] 2025-10-30 00:19:52.789358 | controller | ok 2025-10-30 00:19:52.812555 | 2025-10-30 00:19:52.812653 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-30 00:19:53.369983 | controller | ok 2025-10-30 00:19:53.386105 | 2025-10-30 00:19:53.386572 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-30 00:20:06.796501 | controller | Output suppressed because no_log was given 2025-10-30 00:20:06.814132 | 2025-10-30 00:20:06.814274 | TASK [include_role : prepare-workspace-openshift] 2025-10-30 00:20:06.840739 | controller | skipping: Conditional result was False 2025-10-30 00:20:06.888918 | 2025-10-30 00:20:06.889040 | PLAY [all:!appliance] 2025-10-30 00:20:06.919117 | 2025-10-30 00:20:06.919249 | TASK [Run add-build-sshkey role (RSA)] 2025-10-30 00:20:06.953229 | controller | ok 2025-10-30 00:20:06.994992 | 2025-10-30 00:20:06.995093 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-30 00:20:07.294210 | controller -> localhost | ok 2025-10-30 00:20:07.300418 | 2025-10-30 00:20:07.300495 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-30 00:20:07.340024 | controller | ok 2025-10-30 00:20:07.354327 | controller | included: /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-30 00:20:07.361273 | 2025-10-30 00:20:07.361346 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-30 00:20:07.905898 | controller -> localhost | Generating public/private rsa key pair. 2025-10-30 00:20:07.906172 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/work/d839c35b4d584f6397dfae1e9e90704f_id_rsa. 2025-10-30 00:20:07.906214 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/work/d839c35b4d584f6397dfae1e9e90704f_id_rsa.pub. 2025-10-30 00:20:07.906246 | controller -> localhost | The key fingerprint is: 2025-10-30 00:20:07.906275 | controller -> localhost | SHA256:BTLH6hoYxfjLWXVBEzyZ1K+ApCgxZrVszCZzex6z7s0 zuul-build-sshkey 2025-10-30 00:20:07.906325 | controller -> localhost | The key's randomart image is: 2025-10-30 00:20:07.906354 | controller -> localhost | +---[RSA 2048]----+ 2025-10-30 00:20:07.906381 | controller -> localhost | | +. o.o+** | 2025-10-30 00:20:07.906409 | controller -> localhost | | *+o. ++.*.. | 2025-10-30 00:20:07.906436 | controller -> localhost | | oo=O. = o.. . | 2025-10-30 00:20:07.906462 | controller -> localhost | | o*o.+ ... . | 2025-10-30 00:20:07.906488 | controller -> localhost | | =.=+ S . . | 2025-10-30 00:20:07.906527 | controller -> localhost | | . =o.+ . | 2025-10-30 00:20:07.906564 | controller -> localhost | | oo | 2025-10-30 00:20:07.906593 | controller -> localhost | | .. o | 2025-10-30 00:20:07.906621 | controller -> localhost | | .o E | 2025-10-30 00:20:07.906650 | controller -> localhost | +----[SHA256]-----+ 2025-10-30 00:20:07.906749 | controller -> localhost | ok: Runtime: 0:00:00.084072 2025-10-30 00:20:07.916538 | 2025-10-30 00:20:07.916640 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-30 00:20:07.948894 | controller | ok 2025-10-30 00:20:07.961949 | controller | included: /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-30 00:20:07.973882 | 2025-10-30 00:20:07.973990 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-30 00:20:08.000019 | controller | skipping: Conditional result was False 2025-10-30 00:20:08.006483 | 2025-10-30 00:20:08.006553 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-30 00:20:08.684987 | controller | changed 2025-10-30 00:20:08.693078 | 2025-10-30 00:20:08.693205 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-30 00:20:09.074753 | controller | ok 2025-10-30 00:20:09.082390 | 2025-10-30 00:20:09.082480 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-30 00:20:10.451267 | controller | changed 2025-10-30 00:20:10.460059 | 2025-10-30 00:20:10.460196 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-30 00:20:11.865495 | controller | changed 2025-10-30 00:20:11.874031 | 2025-10-30 00:20:11.874153 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-30 00:20:11.912377 | controller | skipping: Conditional result was False 2025-10-30 00:20:11.928402 | 2025-10-30 00:20:11.928618 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-30 00:20:12.346588 | controller -> localhost | changed 2025-10-30 00:20:12.358596 | 2025-10-30 00:20:12.358724 | TASK [add-build-sshkey : Add back temp key] 2025-10-30 00:20:12.709914 | controller -> localhost | Identity added: /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/work/d839c35b4d584f6397dfae1e9e90704f_id_rsa (zuul-build-sshkey) 2025-10-30 00:20:12.710330 | controller -> localhost | ok: Runtime: 0:00:00.011024 2025-10-30 00:20:12.718055 | 2025-10-30 00:20:12.718142 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-30 00:20:13.336449 | controller | ok 2025-10-30 00:20:13.353087 | 2025-10-30 00:20:13.353208 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-30 00:20:13.387787 | controller | skipping: Conditional result was False 2025-10-30 00:20:13.398574 | 2025-10-30 00:20:13.398640 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-30 00:20:13.437088 | controller | ok 2025-10-30 00:20:13.463362 | 2025-10-30 00:20:13.463491 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-30 00:20:13.726684 | controller -> localhost | ok 2025-10-30 00:20:13.734871 | 2025-10-30 00:20:13.734949 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-30 00:20:13.764209 | controller | ok 2025-10-30 00:20:13.776997 | controller | included: /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-30 00:20:13.783194 | 2025-10-30 00:20:13.783263 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-30 00:20:14.093905 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-30 00:20:14.094115 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/work/d839c35b4d584f6397dfae1e9e90704f_id_ecdsa. 2025-10-30 00:20:14.094146 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/work/d839c35b4d584f6397dfae1e9e90704f_id_ecdsa.pub. 2025-10-30 00:20:14.094177 | controller -> localhost | The key fingerprint is: 2025-10-30 00:20:14.094199 | controller -> localhost | SHA256:XIF7AspHwmExHPegr5Ws+YTch7aTfV4RFFq7/axurA0 zuul-build-sshkey 2025-10-30 00:20:14.094218 | controller -> localhost | The key's randomart image is: 2025-10-30 00:20:14.094236 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-30 00:20:14.094254 | controller -> localhost | | o*+o .. +. | 2025-10-30 00:20:14.094271 | controller -> localhost | | .++oo. = . | 2025-10-30 00:20:14.094288 | controller -> localhost | | ..+ ...o o | 2025-10-30 00:20:14.094306 | controller -> localhost | | oo.oo.. + | 2025-10-30 00:20:14.094322 | controller -> localhost | | .= So o . | 2025-10-30 00:20:14.094339 | controller -> localhost | | . B . . o | 2025-10-30 00:20:14.094359 | controller -> localhost | | * =o. E. o| 2025-10-30 00:20:14.094387 | controller -> localhost | | +oo. .. oo. | 2025-10-30 00:20:14.094407 | controller -> localhost | | o. o. .++ | 2025-10-30 00:20:14.094424 | controller -> localhost | +----[SHA256]-----+ 2025-10-30 00:20:14.094478 | controller -> localhost | ok: Runtime: 0:00:00.010122 2025-10-30 00:20:14.102605 | 2025-10-30 00:20:14.102704 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-30 00:20:14.127172 | controller | ok 2025-10-30 00:20:14.135132 | controller | included: /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-30 00:20:14.144257 | 2025-10-30 00:20:14.144390 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-30 00:20:14.169030 | controller | skipping: Conditional result was False 2025-10-30 00:20:14.176877 | 2025-10-30 00:20:14.176983 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-30 00:20:14.629013 | controller | changed 2025-10-30 00:20:14.645290 | 2025-10-30 00:20:14.645737 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-30 00:20:15.037616 | controller | ok 2025-10-30 00:20:15.056286 | 2025-10-30 00:20:15.056422 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-30 00:20:16.428476 | controller | changed 2025-10-30 00:20:16.442276 | 2025-10-30 00:20:16.442469 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-30 00:20:17.791779 | controller | changed 2025-10-30 00:20:17.798931 | 2025-10-30 00:20:17.799021 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-30 00:20:17.853766 | controller | skipping: Conditional result was False 2025-10-30 00:20:17.863534 | 2025-10-30 00:20:17.863652 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-30 00:20:18.113151 | controller -> localhost | changed 2025-10-30 00:20:18.125127 | 2025-10-30 00:20:18.125205 | TASK [add-build-sshkey : Add back temp key] 2025-10-30 00:20:18.433872 | controller -> localhost | Identity added: /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/work/d839c35b4d584f6397dfae1e9e90704f_id_ecdsa (zuul-build-sshkey) 2025-10-30 00:20:18.434062 | controller -> localhost | ok: Runtime: 0:00:00.021058 2025-10-30 00:20:18.440341 | 2025-10-30 00:20:18.440405 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-30 00:20:18.789503 | controller | ok 2025-10-30 00:20:18.800236 | 2025-10-30 00:20:18.800366 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-30 00:20:18.836755 | controller | skipping: Conditional result was False 2025-10-30 00:20:18.849772 | 2025-10-30 00:20:18.849999 | TASK [include_role : remove-zuul-sshkey] 2025-10-30 00:20:18.876741 | controller | skipping: Conditional result was False 2025-10-30 00:20:18.885260 | 2025-10-30 00:20:18.885365 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-30 00:20:19.347822 | controller | ok: "logs" 2025-10-30 00:20:19.347992 | controller | ok: All items complete 2025-10-30 00:20:19.348020 | 2025-10-30 00:20:19.670120 | controller | ok: "artifacts" 2025-10-30 00:20:19.983809 | controller | ok: "docs" 2025-10-30 00:20:20.001576 | 2025-10-30 00:20:20.001732 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-30 00:20:20.354744 | controller | changed: "logs" 2025-10-30 00:20:20.693720 | controller | changed: "artifacts" 2025-10-30 00:20:21.013050 | controller | changed: "docs" 2025-10-30 00:20:21.069797 | 2025-10-30 00:20:21.069960 | PLAY RECAP 2025-10-30 00:20:21.070213 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-30 00:20:21.070245 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-30 00:20:21.070263 | 2025-10-30 00:20:21.228811 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-30 00:20:21.229701 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-30 00:20:21.789311 | 2025-10-30 00:20:21.789437 | PLAY [all] 2025-10-30 00:20:21.825344 | 2025-10-30 00:20:21.825470 | TASK [Install binary dependencies] 2025-10-30 00:20:21.876480 | controller | ok 2025-10-30 00:20:21.898771 | 2025-10-30 00:20:21.898909 | TASK [bindep : Include find tasks] 2025-10-30 00:20:21.929957 | controller | ok 2025-10-30 00:20:21.939298 | controller | included: /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-30 00:20:21.948486 | 2025-10-30 00:20:21.948580 | TASK [bindep : Look for bindep.txt] 2025-10-30 00:20:22.481633 | controller | ok 2025-10-30 00:20:22.495908 | 2025-10-30 00:20:22.496081 | TASK [bindep : Define bindep_file fact] 2025-10-30 00:20:22.523549 | controller | skipping: Conditional result was False 2025-10-30 00:20:22.536759 | 2025-10-30 00:20:22.536934 | TASK [bindep : Look for other-requirements.txt] 2025-10-30 00:20:22.892257 | controller | ok 2025-10-30 00:20:22.903750 | 2025-10-30 00:20:22.903910 | TASK [bindep : Define bindep_file fact] 2025-10-30 00:20:22.930761 | controller | skipping: Conditional result was False 2025-10-30 00:20:22.943395 | 2025-10-30 00:20:22.943564 | TASK [bindep : Look for bindep fallback file] 2025-10-30 00:20:22.973591 | controller | skipping: Conditional result was False 2025-10-30 00:20:22.986574 | 2025-10-30 00:20:22.986799 | TASK [bindep : Define bindep_file fact] 2025-10-30 00:20:23.013830 | controller | skipping: Conditional result was False 2025-10-30 00:20:23.026043 | 2025-10-30 00:20:23.026185 | TASK [bindep : Include bindep tasks] 2025-10-30 00:20:23.053043 | controller | skipping: Conditional result was False 2025-10-30 00:20:23.062459 | 2025-10-30 00:20:23.062548 | TASK [bindep : Include install tasks] 2025-10-30 00:20:23.096699 | controller | skipping: Conditional result was False 2025-10-30 00:20:23.103369 | 2025-10-30 00:20:23.103452 | LOOP [bindep : Include package tasks] 2025-10-30 00:20:23.158625 | 2025-10-30 00:20:23.158796 | TASK [Run test-setup role] 2025-10-30 00:20:23.177982 | controller | ok 2025-10-30 00:20:23.196792 | 2025-10-30 00:20:23.196883 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-30 00:20:23.548945 | controller | ok 2025-10-30 00:20:23.558852 | 2025-10-30 00:20:23.558936 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-30 00:20:23.692651 | controller | skipping: Conditional result was False 2025-10-30 00:20:23.752330 | 2025-10-30 00:20:23.752429 | PLAY RECAP 2025-10-30 00:20:23.753223 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-30 00:20:23.753274 | 2025-10-30 00:20:23.896578 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-30 00:20:23.897472 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-30 00:20:24.493593 | 2025-10-30 00:20:24.493746 | PLAY [controller] 2025-10-30 00:20:24.513626 | 2025-10-30 00:20:24.513779 | TASK [Create the /root directory] 2025-10-30 00:20:25.259934 | controller | ok 2025-10-30 00:20:25.267746 | 2025-10-30 00:20:25.267994 | TASK [Install glibc-langpack-en] 2025-10-30 00:20:33.419404 | controller | ok: Nothing to do 2025-10-30 00:20:33.433174 | 2025-10-30 00:20:33.433354 | TASK [Ensure controller directory exists] 2025-10-30 00:20:33.870408 | controller | changed 2025-10-30 00:20:33.882143 | 2025-10-30 00:20:33.882281 | TASK [Install container runtime] 2025-10-30 00:20:33.934901 | controller | ok 2025-10-30 00:20:33.970298 | 2025-10-30 00:20:33.970427 | LOOP [ensure-podman : Find distribution installation] 2025-10-30 00:20:33.996997 | controller | ok: "/var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-30 00:20:34.013874 | controller | included: /var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-30 00:20:34.020647 | 2025-10-30 00:20:34.020751 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-30 00:21:51.414623 | controller | changed 2025-10-30 00:21:51.423546 | 2025-10-30 00:21:51.423657 | TASK [ensure-podman : Fetch podman version] 2025-10-30 00:21:52.166346 | controller | Client: Podman Engine 2025-10-30 00:21:52.166430 | controller | Version: 4.6.2 2025-10-30 00:21:52.166480 | controller | API Version: 4.6.2 2025-10-30 00:21:52.166507 | controller | Go Version: go1.19.12 2025-10-30 00:21:52.166545 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-30 00:21:52.166573 | controller | OS/Arch: linux/amd64 2025-10-30 00:21:52.572021 | controller | ok: Runtime: 0:00:00.225679 2025-10-30 00:21:52.580364 | 2025-10-30 00:21:52.580507 | TASK [ensure-podman : Print podman version installed] 2025-10-30 00:21:52.610973 | Podman version: Client: Podman Engine 2025-10-30 00:21:52.611128 | Version: 4.6.2 2025-10-30 00:21:52.611157 | API Version: 4.6.2 2025-10-30 00:21:52.611177 | Go Version: go1.19.12 2025-10-30 00:21:52.611195 | Built: Mon Aug 28 19:38:31 2023 2025-10-30 00:21:52.611214 | OS/Arch: linux/amd64 2025-10-30 00:21:52.616778 | 2025-10-30 00:21:52.616840 | TASK [ensure-podman : Validate podman engine] 2025-10-30 00:21:52.749328 | controller | skipping: Conditional result was False 2025-10-30 00:21:52.758011 | 2025-10-30 00:21:52.758115 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-30 00:21:52.771871 | controller | skipping: Conditional result was False 2025-10-30 00:21:52.784861 | 2025-10-30 00:21:52.784973 | TASK [Ensure python3.8 is present] 2025-10-30 00:21:52.812334 | controller | skipping: Conditional result was False 2025-10-30 00:21:52.819323 | 2025-10-30 00:21:52.819417 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-30 00:21:52.839288 | controller | ok 2025-10-30 00:21:52.861335 | 2025-10-30 00:21:52.861442 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-30 00:21:56.563080 | controller | ok: Nothing to do 2025-10-30 00:21:56.568606 | 2025-10-30 00:21:56.568748 | TASK [our-ensure-python : Also install python3-devel] 2025-10-30 00:22:11.865246 | controller | changed 2025-10-30 00:22:11.892591 | 2025-10-30 00:22:11.892786 | TASK [Run ensure-virtualenv role] 2025-10-30 00:22:11.915639 | controller | ok 2025-10-30 00:22:11.948349 | 2025-10-30 00:22:11.948495 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-30 00:22:12.350805 | controller | /usr/bin/virtualenv 2025-10-30 00:22:12.584527 | controller | ok: Runtime: 0:00:00.004687 2025-10-30 00:22:12.591302 | 2025-10-30 00:22:12.591377 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-30 00:22:12.629782 | controller | skipping: Conditional result was False 2025-10-30 00:22:12.630241 | controller | ok: All items complete 2025-10-30 00:22:12.630303 | 2025-10-30 00:22:12.660874 | 2025-10-30 00:22:12.661023 | TASK [Find the full path of the Python interpreter] 2025-10-30 00:22:13.133552 | controller | /usr/bin/python3 2025-10-30 00:22:13.341927 | controller | ok 2025-10-30 00:22:13.348034 | 2025-10-30 00:22:13.348113 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-30 00:22:14.765965 | controller | created virtual environment CPython3.11.0.final.0-64 in 745ms 2025-10-30 00:22:14.823736 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-30 00:22:14.824450 | 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-30 00:22:14.824476 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-30 00:22:14.824499 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-30 00:22:14.995923 | controller | changed 2025-10-30 00:22:15.005540 | 2025-10-30 00:22:15.005639 | TASK [Set selinux package] 2025-10-30 00:22:15.036285 | controller | ok 2025-10-30 00:22:15.041851 | 2025-10-30 00:22:15.041918 | TASK [Set selinux package (Fedora)] 2025-10-30 00:22:15.087404 | controller | ok 2025-10-30 00:22:15.094061 | 2025-10-30 00:22:15.094140 | TASK [Install selinux into virtualenv] 2025-10-30 00:22:17.683836 | controller | Collecting selinux-please-lie-to-me 2025-10-30 00:22:17.775060 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-30 00:22:18.300086 | controller | Collecting setuptools<50.0.0 2025-10-30 00:22:18.315081 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-30 00:22:18.452834 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.0 MB/s eta 0:00:00 2025-10-30 00:22:18.599903 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-30 00:22:18.600217 | controller | Attempting uninstall: setuptools 2025-10-30 00:22:18.605038 | controller | Found existing installation: setuptools 62.6.0 2025-10-30 00:22:18.715080 | controller | Uninstalling setuptools-62.6.0: 2025-10-30 00:22:18.730190 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-30 00:22:19.489864 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-30 00:22:19.704589 | controller | 2025-10-30 00:22:19.920413 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-10-30 00:22:19.920469 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-30 00:22:20.233785 | controller | ok: Runtime: 0:00:04.368053 2025-10-30 00:22:20.246523 | 2025-10-30 00:22:20.246943 | TASK [Install pytest-forked into virtualenv] 2025-10-30 00:22:21.488548 | controller | Collecting pytest-forked 2025-10-30 00:22:21.577006 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-30 00:22:21.636722 | controller | Collecting py 2025-10-30 00:22:21.650221 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-30 00:22:21.684484 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00 2025-10-30 00:22:21.858251 | controller | Collecting pytest>=3.10 2025-10-30 00:22:21.871697 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-30 00:22:21.912255 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 9.8 MB/s eta 0:00:00 2025-10-30 00:22:21.968244 | controller | Collecting iniconfig>=1 2025-10-30 00:22:21.981592 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-30 00:22:22.049079 | controller | Collecting packaging>=20 2025-10-30 00:22:22.062270 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-30 00:22:22.071529 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.0 MB/s eta 0:00:00 2025-10-30 00:22:22.118179 | controller | Collecting pluggy<2,>=1.5 2025-10-30 00:22:22.131312 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-30 00:22:22.204996 | controller | Collecting pygments>=2.7.2 2025-10-30 00:22:22.235993 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-30 00:22:22.267618 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 43.9 MB/s eta 0:00:00 2025-10-30 00:22:22.397319 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-30 00:22:24.590410 | 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-30 00:22:24.606173 | controller | 2025-10-30 00:22:24.791106 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-10-30 00:22:24.791158 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-30 00:22:24.949580 | controller | ok: Runtime: 0:00:04.041048 2025-10-30 00:22:24.961719 | 2025-10-30 00:22:24.961867 | TASK [Update pip] 2025-10-30 00:22:26.069314 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-30 00:22:26.341733 | controller | Collecting pip 2025-10-30 00:22:26.447701 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-10-30 00:22:26.542730 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 19.7 MB/s eta 0:00:00 2025-10-30 00:22:26.707583 | controller | Installing collected packages: pip 2025-10-30 00:22:26.707898 | controller | Attempting uninstall: pip 2025-10-30 00:22:26.712314 | controller | Found existing installation: pip 22.2.2 2025-10-30 00:22:26.966540 | controller | Uninstalling pip-22.2.2: 2025-10-30 00:22:26.995874 | controller | Successfully uninstalled pip-22.2.2 2025-10-30 00:22:28.733315 | controller | Successfully installed pip-25.3 2025-10-30 00:22:29.120419 | controller | ok: Runtime: 0:00:03.434964 2025-10-30 00:22:29.133237 | 2025-10-30 00:22:29.133396 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-30 00:22:29.647457 | controller | changed 2025-10-30 00:22:29.655338 | 2025-10-30 00:22:29.655443 | TASK [Install ansible into virtualenv] 2025-10-30 00:22:30.658231 | controller | Processing ./src/github.com/ansible/ansible 2025-10-30 00:22:30.664592 | controller | Installing build dependencies: started 2025-10-30 00:22:32.431509 | controller | Installing build dependencies: finished with status 'done' 2025-10-30 00:22:33.934500 | controller | Getting requirements to build wheel: started 2025-10-30 00:22:33.934567 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-30 00:22:33.936246 | controller | Preparing metadata (pyproject.toml): started 2025-10-30 00:22:34.853501 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-30 00:22:34.858288 | 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-30 00:22:34.863160 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-30 00:22:35.315479 | controller | ERROR 2025-10-30 00:22:35.315757 | controller | { 2025-10-30 00:22:35.315818 | controller | "delta": "0:00:04.913759", 2025-10-30 00:22:35.315855 | controller | "end": "2025-10-30 00:22:35.007808", 2025-10-30 00:22:35.315889 | controller | "msg": "non-zero return code", 2025-10-30 00:22:35.315933 | controller | "rc": 1, 2025-10-30 00:22:35.315972 | controller | "start": "2025-10-30 00:22:30.094049" 2025-10-30 00:22:35.316000 | controller | } failure 2025-10-30 00:22:35.318166 | 2025-10-30 00:22:35.318238 | PLAY RECAP 2025-10-30 00:22:35.318296 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-30 00:22:35.318327 | 2025-10-30 00:22:35.463478 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-30 00:22:35.465761 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-30 00:22:36.128860 | 2025-10-30 00:22:36.129017 | PLAY [all] 2025-10-30 00:22:36.154196 | 2025-10-30 00:22:36.154343 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-30 00:22:36.937401 | controller | changed: non-zero return code 2025-10-30 00:22:36.949615 | 2025-10-30 00:22:36.949765 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-30 00:22:36.965983 | controller | skipping: Conditional result was False 2025-10-30 00:22:36.978365 | 2025-10-30 00:22:36.978515 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-30 00:22:37.017349 | 2025-10-30 00:22:37.017540 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-30 00:22:37.047158 | 2025-10-30 00:22:37.047315 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-30 00:22:37.061468 | controller | skipping: Conditional result was False 2025-10-30 00:22:37.068316 | 2025-10-30 00:22:37.068411 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-30 00:22:37.091287 | 2025-10-30 00:22:37.091505 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-30 00:22:37.107460 | controller | skipping: Conditional result was False 2025-10-30 00:22:37.114191 | 2025-10-30 00:22:37.114279 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-30 00:22:37.139697 | controller | skipping: Conditional result was False 2025-10-30 00:22:37.148513 | 2025-10-30 00:22:37.148627 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-30 00:22:37.162772 | controller | skipping: Conditional result was False 2025-10-30 00:22:37.196076 | 2025-10-30 00:22:37.196179 | PLAY RECAP 2025-10-30 00:22:37.196219 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-30 00:22:37.196240 | 2025-10-30 00:22:37.284133 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-30 00:22:37.285168 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-30 00:22:37.891176 | 2025-10-30 00:22:37.891295 | PLAY [all:!appliance*] 2025-10-30 00:22:37.912598 | 2025-10-30 00:22:37.912719 | TASK [unregister the node] 2025-10-30 00:22:38.040321 | controller | skipping: Conditional result was False 2025-10-30 00:22:38.054084 | 2025-10-30 00:22:38.054437 | TASK [include_role : fetch-output] 2025-10-30 00:22:38.090219 | controller | ok 2025-10-30 00:22:38.126494 | 2025-10-30 00:22:38.126644 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-30 00:22:38.171182 | controller | skipping: Conditional result was False 2025-10-30 00:22:38.177718 | 2025-10-30 00:22:38.177896 | TASK [fetch-output : Set log path for single node] 2025-10-30 00:22:38.221714 | controller | ok 2025-10-30 00:22:38.227363 | 2025-10-30 00:22:38.227432 | LOOP [fetch-output : Ensure local output dirs] 2025-10-30 00:22:38.641638 | controller -> localhost | ok: "/var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/work/logs" 2025-10-30 00:22:38.881915 | controller -> localhost | changed: "/var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/work/artifacts" 2025-10-30 00:22:39.139298 | controller -> localhost | changed: "/var/lib/zuul/builds/d839c35b4d584f6397dfae1e9e90704f/work/docs" 2025-10-30 00:22:39.157159 | 2025-10-30 00:22:39.157296 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-30 00:22:40.397427 | controller | changed: 2025-10-30 00:22:40.397630 | controller | .d..t...... ./ 2025-10-30 00:22:40.397684 | controller | cd+++++++++ controller/ 2025-10-30 00:22:40.397724 | controller | changed: All items complete 2025-10-30 00:22:40.397745 | 2025-10-30 00:22:41.351342 | controller | changed: .d..t...... ./ 2025-10-30 00:22:42.322845 | controller | changed: .d..t...... ./ 2025-10-30 00:22:42.344155 | 2025-10-30 00:22:42.344229 | TASK [include_role : fetch-output-openshift] 2025-10-30 00:22:42.370715 | controller | skipping: Conditional result was False 2025-10-30 00:22:42.379564 | 2025-10-30 00:22:42.379706 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-30 00:22:42.422998 | controller | skipping: Conditional result was False 2025-10-30 00:22:42.433101 | controller | skipping: Conditional result was False 2025-10-30 00:22:42.463547 | 2025-10-30 00:22:42.463674 | PLAY [localhost] 2025-10-30 00:22:42.476453 | 2025-10-30 00:22:42.476572 | TASK [Run Zuul manifest role] 2025-10-30 00:22:42.496012 | localhost | ok 2025-10-30 00:22:42.510976 | 2025-10-30 00:22:42.511084 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-30 00:22:42.924369 | localhost | changed 2025-10-30 00:22:42.930027 | 2025-10-30 00:22:42.930101 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-30 00:22:42.970544 | localhost | ok 2025-10-30 00:22:42.979314 | 2025-10-30 00:22:42.979537 | TASK [Set zuul-log-path fact] 2025-10-30 00:22:43.000095 | localhost | ok 2025-10-30 00:22:43.016825 | 2025-10-30 00:22:43.016961 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-30 00:22:43.045549 | localhost | ok 2025-10-30 00:22:43.053571 | 2025-10-30 00:22:43.053649 | LOOP [Run upload-logs-swift role] 2025-10-30 00:22:43.098554 | localhost | Output suppressed because no_log was given 2025-10-30 00:22:43.135288 | 2025-10-30 00:22:43.135421 | TASK [Set zuul-log-path fact] 2025-10-30 00:22:43.160267 | localhost | skipping: Conditional result was False 2025-10-30 00:22:43.167002 | 2025-10-30 00:22:43.167093 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-30 00:22:43.598498 | localhost -> localhost | ok: Runtime: 0:00:00.009181 2025-10-30 00:22:43.603900 | 2025-10-30 00:22:43.603965 | TASK [upload-logs-swift : Upload logs to swift]