2025-11-01 00:06:56.207175 | Job console starting... 2025-11-01 00:06:56.217664 | Updating repositories 2025-11-01 00:06:56.450046 | Preparing job workspace 2025-11-01 00:07:01.139491 | Running Ansible setup... 2025-11-01 00:07:09.021413 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-01 00:07:09.650384 | 2025-11-01 00:07:09.650510 | PLAY [localhost] 2025-11-01 00:07:09.659213 | 2025-11-01 00:07:09.659311 | TASK [Gathering Facts] 2025-11-01 00:07:10.580359 | localhost | ok 2025-11-01 00:07:10.594934 | 2025-11-01 00:07:10.595019 | TASK [Setup log path fact] 2025-11-01 00:07:10.614794 | localhost | ok 2025-11-01 00:07:10.631415 | 2025-11-01 00:07:10.631556 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-01 00:07:10.652831 | localhost | ok 2025-11-01 00:07:10.665362 | 2025-11-01 00:07:10.665504 | TASK [emit-job-header : Print job information] 2025-11-01 00:07:10.696123 | # Job Information 2025-11-01 00:07:10.696657 | Ansible Version: 2.15.12 2025-11-01 00:07:10.696755 | Job: ansible-test-sanity-docker-milestone 2025-11-01 00:07:10.696789 | Pipeline: periodic 2025-11-01 00:07:10.696818 | Executor: ze02.softwarefactory-project.io 2025-11-01 00:07:10.696846 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-01 00:07:10.696877 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/89e/ansible/89e0da849a0b4b869de7788416dba9c4/ 2025-11-01 00:07:10.696906 | Event ID: a664f74adefa4145bbf2cab5da247121 2025-11-01 00:07:10.702409 | 2025-11-01 00:07:10.702519 | LOOP [emit-job-header : Print node information] 2025-11-01 00:07:10.819069 | localhost | ok: 2025-11-01 00:07:10.819338 | localhost | # Node Information 2025-11-01 00:07:10.819378 | localhost | Inventory Hostname: controller 2025-11-01 00:07:10.819408 | localhost | Hostname: np0005508777 2025-11-01 00:07:10.819436 | localhost | Username: zuul 2025-11-01 00:07:10.819466 | localhost | Distro: Fedora 37 2025-11-01 00:07:10.819492 | localhost | Provider: ansible-vexxhost-ams1 2025-11-01 00:07:10.819518 | localhost | Region: ams1 2025-11-01 00:07:10.819544 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-01 00:07:10.819568 | localhost | Product Name: OpenStack Nova 2025-11-01 00:07:10.819594 | localhost | Interface IP: 38.129.16.180 2025-11-01 00:07:10.840996 | 2025-11-01 00:07:10.841128 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-01 00:07:11.265092 | localhost -> localhost | changed 2025-11-01 00:07:11.272961 | 2025-11-01 00:07:11.273084 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-01 00:07:12.218350 | localhost -> localhost | changed 2025-11-01 00:07:12.247646 | 2025-11-01 00:07:12.247811 | PLAY [all:!appliance*] 2025-11-01 00:07:12.267772 | 2025-11-01 00:07:12.267865 | TASK [include_role : start-zuul-console] 2025-11-01 00:07:12.286579 | controller | ok 2025-11-01 00:07:12.300611 | 2025-11-01 00:07:12.300724 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-01 00:07:13.294473 | controller | ok 2025-11-01 00:07:13.335172 | 2025-11-01 00:07:13.335576 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-01 00:07:15.173958 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-01 00:07:15.188085 | 2025-11-01 00:07:15.188247 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-01 00:07:15.558073 | controller | skipping: Conditional result was False 2025-11-01 00:07:15.571717 | 2025-11-01 00:07:15.571894 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-01 00:07:15.598902 | controller | skipping: Conditional result was False 2025-11-01 00:07:15.611868 | 2025-11-01 00:07:15.612037 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-01 00:07:15.639132 | controller | skipping: Conditional result was False 2025-11-01 00:07:15.649515 | 2025-11-01 00:07:15.649659 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-01 00:07:15.674968 | controller | skipping: Conditional result was False 2025-11-01 00:07:15.684752 | 2025-11-01 00:07:15.684907 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-01 00:07:15.710095 | controller | skipping: Conditional result was False 2025-11-01 00:07:15.723649 | 2025-11-01 00:07:15.723846 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-01 00:07:15.751417 | controller | skipping: Conditional result was False 2025-11-01 00:07:15.770285 | 2025-11-01 00:07:15.770434 | TASK [Disable Fedora Modular] 2025-11-01 00:07:16.847592 | controller | changed 2025-11-01 00:07:16.857141 | 2025-11-01 00:07:16.857306 | TASK [Enable EPEL] 2025-11-01 00:07:16.884046 | controller | skipping: Conditional result was False 2025-11-01 00:07:16.892776 | 2025-11-01 00:07:16.892908 | TASK [Register the RHEL node] 2025-11-01 00:07:17.320248 | 2025-11-01 00:07:17.320435 | TASK [Show the subscription-manager status] 2025-11-01 00:07:17.694393 | controller | skipping: Conditional result was False 2025-11-01 00:07:17.703445 | 2025-11-01 00:07:17.703591 | TASK [Enable EPEL on RHEL] 2025-11-01 00:07:18.086363 | controller | skipping: Conditional result was False 2025-11-01 00:07:18.101248 | 2025-11-01 00:07:18.101406 | TASK [Install git and tox] 2025-11-01 00:09:08.436636 | controller | changed 2025-11-01 00:09:08.445560 | 2025-11-01 00:09:08.445687 | TASK [include_role : prepare-workspace] 2025-11-01 00:09:08.494848 | controller | ok 2025-11-01 00:09:08.527211 | 2025-11-01 00:09:08.527301 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-01 00:09:09.355132 | controller | ok 2025-11-01 00:09:09.371524 | 2025-11-01 00:09:09.371733 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-01 00:09:25.353210 | controller | Output suppressed because no_log was given 2025-11-01 00:09:25.378069 | 2025-11-01 00:09:25.378194 | TASK [include_role : prepare-workspace-openshift] 2025-11-01 00:09:25.403605 | controller | skipping: Conditional result was False 2025-11-01 00:09:25.428042 | 2025-11-01 00:09:25.428113 | PLAY [all:!appliance] 2025-11-01 00:09:25.444131 | 2025-11-01 00:09:25.444207 | TASK [Run add-build-sshkey role (RSA)] 2025-11-01 00:09:25.474804 | controller | ok 2025-11-01 00:09:25.490593 | 2025-11-01 00:09:25.490719 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-01 00:09:25.759094 | controller -> localhost | ok 2025-11-01 00:09:25.766623 | 2025-11-01 00:09:25.766713 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-01 00:09:25.796338 | controller | ok 2025-11-01 00:09:25.811482 | controller | included: /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-01 00:09:25.817622 | 2025-11-01 00:09:25.817724 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-01 00:09:26.340376 | controller -> localhost | Generating public/private rsa key pair. 2025-11-01 00:09:26.340570 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/work/89e0da849a0b4b869de7788416dba9c4_id_rsa. 2025-11-01 00:09:26.340601 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/work/89e0da849a0b4b869de7788416dba9c4_id_rsa.pub. 2025-11-01 00:09:26.340622 | controller -> localhost | The key fingerprint is: 2025-11-01 00:09:26.340642 | controller -> localhost | SHA256:VN9XZpaw1Q35tV35Ak9DgiugQ5+hPYB6rQFz9QWNCF0 zuul-build-sshkey 2025-11-01 00:09:26.340675 | controller -> localhost | The key's randomart image is: 2025-11-01 00:09:26.340699 | controller -> localhost | +---[RSA 2048]----+ 2025-11-01 00:09:26.340718 | controller -> localhost | | .=.oE+. ...o++X| 2025-11-01 00:09:26.340737 | controller -> localhost | |o o =.+......o***| 2025-11-01 00:09:26.340755 | controller -> localhost | | = o *.+. ..=.oB| 2025-11-01 00:09:26.340772 | controller -> localhost | |. o = =.. . oo+| 2025-11-01 00:09:26.340790 | controller -> localhost | | . o . .S. . | 2025-11-01 00:09:26.340817 | controller -> localhost | | . | 2025-11-01 00:09:26.340840 | controller -> localhost | | | 2025-11-01 00:09:26.340859 | controller -> localhost | | | 2025-11-01 00:09:26.340877 | controller -> localhost | | | 2025-11-01 00:09:26.340898 | controller -> localhost | +----[SHA256]-----+ 2025-11-01 00:09:26.340944 | controller -> localhost | ok: Runtime: 0:00:00.078257 2025-11-01 00:09:26.347532 | 2025-11-01 00:09:26.347675 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-01 00:09:26.378883 | controller | ok 2025-11-01 00:09:26.389471 | controller | included: /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-01 00:09:26.398893 | 2025-11-01 00:09:26.398962 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-01 00:09:26.423050 | controller | skipping: Conditional result was False 2025-11-01 00:09:26.430717 | 2025-11-01 00:09:26.430811 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-01 00:09:27.507093 | controller | changed 2025-11-01 00:09:27.521747 | 2025-11-01 00:09:27.521899 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-01 00:09:28.163498 | controller | ok 2025-11-01 00:09:28.176359 | 2025-11-01 00:09:28.176504 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-01 00:09:31.190959 | controller | changed 2025-11-01 00:09:31.204485 | 2025-11-01 00:09:31.204691 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-01 00:09:34.150086 | controller | changed 2025-11-01 00:09:34.163753 | 2025-11-01 00:09:34.163851 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-01 00:09:34.178633 | controller | skipping: Conditional result was False 2025-11-01 00:09:34.189004 | 2025-11-01 00:09:34.189113 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-01 00:09:34.590746 | controller -> localhost | changed 2025-11-01 00:09:34.603909 | 2025-11-01 00:09:34.604025 | TASK [add-build-sshkey : Add back temp key] 2025-11-01 00:09:34.916446 | controller -> localhost | Identity added: /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/work/89e0da849a0b4b869de7788416dba9c4_id_rsa (zuul-build-sshkey) 2025-11-01 00:09:34.916641 | controller -> localhost | ok: Runtime: 0:00:00.022986 2025-11-01 00:09:34.925288 | 2025-11-01 00:09:34.925413 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-01 00:09:35.828901 | controller | ok 2025-11-01 00:09:35.838437 | 2025-11-01 00:09:35.838575 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-01 00:09:35.866557 | controller | skipping: Conditional result was False 2025-11-01 00:09:35.885482 | 2025-11-01 00:09:35.885616 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-01 00:09:35.920803 | controller | ok 2025-11-01 00:09:35.948866 | 2025-11-01 00:09:35.949022 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-01 00:09:36.200511 | controller -> localhost | ok 2025-11-01 00:09:36.210769 | 2025-11-01 00:09:36.210899 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-01 00:09:36.233384 | controller | ok 2025-11-01 00:09:36.245244 | controller | included: /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-01 00:09:36.251634 | 2025-11-01 00:09:36.251749 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-01 00:09:36.551190 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-01 00:09:36.551518 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/work/89e0da849a0b4b869de7788416dba9c4_id_ecdsa. 2025-11-01 00:09:36.551586 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/work/89e0da849a0b4b869de7788416dba9c4_id_ecdsa.pub. 2025-11-01 00:09:36.551650 | controller -> localhost | The key fingerprint is: 2025-11-01 00:09:36.551790 | controller -> localhost | SHA256:MWgQL4aqK+e1KrXeQtRW8fWrPhNZoSKJPtpUtrcB1W8 zuul-build-sshkey 2025-11-01 00:09:36.551840 | controller -> localhost | The key's randomart image is: 2025-11-01 00:09:36.551886 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-01 00:09:36.551943 | controller -> localhost | | o... .. | 2025-11-01 00:09:36.552003 | controller -> localhost | | . o.o..... | 2025-11-01 00:09:36.552048 | controller -> localhost | | ..oo+o+ o.. | 2025-11-01 00:09:36.552093 | controller -> localhost | | ...+o* .o. E. | 2025-11-01 00:09:36.552154 | controller -> localhost | |.. o o +S. +. | 2025-11-01 00:09:36.552214 | controller -> localhost | |. o + . o o. | 2025-11-01 00:09:36.552269 | controller -> localhost | |.o =.. . o.. | 2025-11-01 00:09:36.552312 | controller -> localhost | |o.=o.. ..o | 2025-11-01 00:09:36.552350 | controller -> localhost | |o=+oo .o | 2025-11-01 00:09:36.552387 | controller -> localhost | +----[SHA256]-----+ 2025-11-01 00:09:36.552485 | controller -> localhost | ok: Runtime: 0:00:00.007388 2025-11-01 00:09:36.568434 | 2025-11-01 00:09:36.568570 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-01 00:09:36.608726 | controller | ok 2025-11-01 00:09:36.666124 | controller | included: /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-01 00:09:36.675873 | 2025-11-01 00:09:36.675949 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-01 00:09:36.690163 | controller | skipping: Conditional result was False 2025-11-01 00:09:36.700390 | 2025-11-01 00:09:36.700527 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-01 00:09:37.564842 | controller | changed 2025-11-01 00:09:37.570638 | 2025-11-01 00:09:37.570739 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-01 00:09:38.180257 | controller | ok 2025-11-01 00:09:38.190034 | 2025-11-01 00:09:38.190162 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-01 00:09:41.111920 | controller | changed 2025-11-01 00:09:41.118429 | 2025-11-01 00:09:41.118514 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-01 00:09:44.038107 | controller | changed 2025-11-01 00:09:44.044817 | 2025-11-01 00:09:44.044906 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-01 00:09:44.069485 | controller | skipping: Conditional result was False 2025-11-01 00:09:44.078729 | 2025-11-01 00:09:44.078838 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-01 00:09:44.349225 | controller -> localhost | changed 2025-11-01 00:09:44.368289 | 2025-11-01 00:09:44.368443 | TASK [add-build-sshkey : Add back temp key] 2025-11-01 00:09:44.630091 | controller -> localhost | Identity added: /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/work/89e0da849a0b4b869de7788416dba9c4_id_ecdsa (zuul-build-sshkey) 2025-11-01 00:09:44.630366 | controller -> localhost | ok: Runtime: 0:00:00.007690 2025-11-01 00:09:44.638325 | 2025-11-01 00:09:44.638413 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-01 00:09:45.301496 | controller | ok 2025-11-01 00:09:45.308264 | 2025-11-01 00:09:45.308354 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-01 00:09:45.343067 | controller | skipping: Conditional result was False 2025-11-01 00:09:45.363410 | 2025-11-01 00:09:45.363554 | TASK [include_role : remove-zuul-sshkey] 2025-11-01 00:09:45.390178 | controller | skipping: Conditional result was False 2025-11-01 00:09:45.400051 | 2025-11-01 00:09:45.400164 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-01 00:09:46.042882 | controller | ok: "logs" 2025-11-01 00:09:46.043172 | controller | ok: All items complete 2025-11-01 00:09:46.043202 | 2025-11-01 00:09:46.648446 | controller | ok: "artifacts" 2025-11-01 00:09:47.251827 | controller | ok: "docs" 2025-11-01 00:09:47.261846 | 2025-11-01 00:09:47.261959 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-01 00:09:47.897452 | controller | changed: "logs" 2025-11-01 00:09:48.485337 | controller | changed: "artifacts" 2025-11-01 00:09:49.080446 | controller | changed: "docs" 2025-11-01 00:09:49.119624 | 2025-11-01 00:09:49.119744 | PLAY RECAP 2025-11-01 00:09:49.119788 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-01 00:09:49.119819 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-01 00:09:49.119838 | 2025-11-01 00:09:49.252208 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-01 00:09:49.253106 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-01 00:09:49.910231 | 2025-11-01 00:09:49.910391 | PLAY [all] 2025-11-01 00:09:49.938443 | 2025-11-01 00:09:49.938628 | TASK [Install binary dependencies] 2025-11-01 00:09:49.989868 | controller | ok 2025-11-01 00:09:50.010963 | 2025-11-01 00:09:50.011120 | TASK [bindep : Include find tasks] 2025-11-01 00:09:50.042535 | controller | ok 2025-11-01 00:09:50.051750 | controller | included: /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-01 00:09:50.058966 | 2025-11-01 00:09:50.059088 | TASK [bindep : Look for bindep.txt] 2025-11-01 00:09:50.950620 | controller | ok 2025-11-01 00:09:50.958242 | 2025-11-01 00:09:50.958356 | TASK [bindep : Define bindep_file fact] 2025-11-01 00:09:50.978588 | controller | skipping: Conditional result was False 2025-11-01 00:09:50.985329 | 2025-11-01 00:09:50.985436 | TASK [bindep : Look for other-requirements.txt] 2025-11-01 00:09:51.578633 | controller | ok 2025-11-01 00:09:51.586613 | 2025-11-01 00:09:51.586753 | TASK [bindep : Define bindep_file fact] 2025-11-01 00:09:51.611894 | controller | skipping: Conditional result was False 2025-11-01 00:09:51.624552 | 2025-11-01 00:09:51.624741 | TASK [bindep : Look for bindep fallback file] 2025-11-01 00:09:51.652088 | controller | skipping: Conditional result was False 2025-11-01 00:09:51.660071 | 2025-11-01 00:09:51.660172 | TASK [bindep : Define bindep_file fact] 2025-11-01 00:09:51.684127 | controller | skipping: Conditional result was False 2025-11-01 00:09:51.691319 | 2025-11-01 00:09:51.691417 | TASK [bindep : Include bindep tasks] 2025-11-01 00:09:51.736520 | controller | skipping: Conditional result was False 2025-11-01 00:09:51.744832 | 2025-11-01 00:09:51.744977 | TASK [bindep : Include install tasks] 2025-11-01 00:09:51.769295 | controller | skipping: Conditional result was False 2025-11-01 00:09:51.777405 | 2025-11-01 00:09:51.777528 | LOOP [bindep : Include package tasks] 2025-11-01 00:09:51.851302 | 2025-11-01 00:09:51.851530 | TASK [Run test-setup role] 2025-11-01 00:09:51.880112 | controller | ok 2025-11-01 00:09:51.927479 | 2025-11-01 00:09:51.927682 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-01 00:09:52.600210 | controller | ok 2025-11-01 00:09:52.607127 | 2025-11-01 00:09:52.607230 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-01 00:09:52.964118 | controller | skipping: Conditional result was False 2025-11-01 00:09:53.000820 | 2025-11-01 00:09:53.000936 | PLAY RECAP 2025-11-01 00:09:53.000992 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-01 00:09:53.001024 | 2025-11-01 00:09:53.130722 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-01 00:09:53.131999 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-01 00:09:53.820491 | 2025-11-01 00:09:53.820710 | PLAY [controller] 2025-11-01 00:09:53.842695 | 2025-11-01 00:09:53.842851 | TASK [Create the /root directory] 2025-11-01 00:09:54.857407 | controller | ok 2025-11-01 00:09:54.867100 | 2025-11-01 00:09:54.867812 | TASK [Install glibc-langpack-en] 2025-11-01 00:10:02.025607 | controller | ok: Nothing to do 2025-11-01 00:10:02.037681 | 2025-11-01 00:10:02.037806 | TASK [Ensure controller directory exists] 2025-11-01 00:10:02.868243 | controller | changed 2025-11-01 00:10:02.885127 | 2025-11-01 00:10:02.886938 | TASK [Install container runtime] 2025-11-01 00:10:03.060584 | controller | ok 2025-11-01 00:10:03.159632 | 2025-11-01 00:10:03.165139 | LOOP [ensure-podman : Find distribution installation] 2025-11-01 00:10:03.281182 | controller | ok: "/var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-01 00:10:03.294906 | controller | included: /var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-01 00:10:03.343975 | 2025-11-01 00:10:03.344121 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-01 00:11:50.000284 | controller | changed 2025-11-01 00:11:50.011154 | 2025-11-01 00:11:50.011268 | TASK [ensure-podman : Fetch podman version] 2025-11-01 00:11:51.090596 | controller | Client: Podman Engine 2025-11-01 00:11:51.090700 | controller | Version: 4.6.2 2025-11-01 00:11:51.090745 | controller | API Version: 4.6.2 2025-11-01 00:11:51.090787 | controller | Go Version: go1.19.12 2025-11-01 00:11:51.090838 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-01 00:11:51.090882 | controller | OS/Arch: linux/amd64 2025-11-01 00:11:51.375093 | controller | ok: Runtime: 0:00:00.258610 2025-11-01 00:11:51.383552 | 2025-11-01 00:11:51.383692 | TASK [ensure-podman : Print podman version installed] 2025-11-01 00:11:51.421986 | Podman version: Client: Podman Engine 2025-11-01 00:11:51.422308 | Version: 4.6.2 2025-11-01 00:11:51.422379 | API Version: 4.6.2 2025-11-01 00:11:51.422426 | Go Version: go1.19.12 2025-11-01 00:11:51.422464 | Built: Mon Aug 28 19:38:31 2023 2025-11-01 00:11:51.422505 | OS/Arch: linux/amd64 2025-11-01 00:11:51.435641 | 2025-11-01 00:11:51.435789 | TASK [ensure-podman : Validate podman engine] 2025-11-01 00:11:51.792229 | controller | skipping: Conditional result was False 2025-11-01 00:11:51.809036 | 2025-11-01 00:11:51.809212 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-01 00:11:51.825971 | controller | skipping: Conditional result was False 2025-11-01 00:11:51.853179 | 2025-11-01 00:11:51.853314 | TASK [Ensure python3.8 is present] 2025-11-01 00:11:51.868584 | controller | skipping: Conditional result was False 2025-11-01 00:11:51.882138 | 2025-11-01 00:11:51.882285 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-01 00:11:51.906361 | controller | ok 2025-11-01 00:11:51.934983 | 2025-11-01 00:11:51.935116 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-01 00:11:55.017246 | controller | ok: Nothing to do 2025-11-01 00:11:55.030784 | 2025-11-01 00:11:55.030949 | TASK [our-ensure-python : Also install python3-devel] 2025-11-01 00:12:08.508350 | controller | changed 2025-11-01 00:12:08.536121 | 2025-11-01 00:12:08.536289 | TASK [Run ensure-virtualenv role] 2025-11-01 00:12:08.568344 | controller | ok 2025-11-01 00:12:08.600483 | 2025-11-01 00:12:08.600629 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-01 00:12:09.334278 | controller | /usr/bin/virtualenv 2025-11-01 00:12:09.462876 | controller | ok: Runtime: 0:00:00.004709 2025-11-01 00:12:09.478341 | 2025-11-01 00:12:09.478525 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-01 00:12:09.506503 | controller | skipping: Conditional result was False 2025-11-01 00:12:09.506808 | controller | ok: All items complete 2025-11-01 00:12:09.506849 | 2025-11-01 00:12:09.538165 | 2025-11-01 00:12:09.538336 | TASK [Find the full path of the Python interpreter] 2025-11-01 00:12:10.112242 | controller | /usr/bin/python3 2025-11-01 00:12:10.408656 | controller | ok 2025-11-01 00:12:10.415577 | 2025-11-01 00:12:10.415689 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-01 00:12:12.093146 | controller | created virtual environment CPython3.11.0.final.0-64 in 834ms 2025-11-01 00:12:12.142316 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-01 00:12:12.142366 | 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-11-01 00:12:12.142384 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-01 00:12:12.142405 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-01 00:12:12.294545 | controller | changed 2025-11-01 00:12:12.304706 | 2025-11-01 00:12:12.304798 | TASK [Set selinux package] 2025-11-01 00:12:12.340276 | controller | ok 2025-11-01 00:12:12.347454 | 2025-11-01 00:12:12.347539 | TASK [Set selinux package (Fedora)] 2025-11-01 00:12:12.412446 | controller | ok 2025-11-01 00:12:12.422199 | 2025-11-01 00:12:12.422294 | TASK [Install selinux into virtualenv] 2025-11-01 00:12:14.995281 | controller | Collecting selinux-please-lie-to-me 2025-11-01 00:12:15.051217 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-01 00:12:15.523420 | controller | Collecting setuptools<50.0.0 2025-11-01 00:12:15.528699 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-01 00:12:15.573624 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 20.0 MB/s eta 0:00:00 2025-11-01 00:12:15.692637 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-01 00:12:15.692948 | controller | Attempting uninstall: setuptools 2025-11-01 00:12:15.696607 | controller | Found existing installation: setuptools 62.6.0 2025-11-01 00:12:15.796959 | controller | Uninstalling setuptools-62.6.0: 2025-11-01 00:12:15.808986 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-01 00:12:16.475102 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-01 00:12:16.652995 | controller | 2025-11-01 00:12:16.879740 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-01 00:12:16.879788 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-01 00:12:17.306040 | controller | ok: Runtime: 0:00:03.709023 2025-11-01 00:12:17.314953 | 2025-11-01 00:12:17.315051 | TASK [Install pytest-forked into virtualenv] 2025-11-01 00:12:18.645463 | controller | Collecting pytest-forked 2025-11-01 00:12:18.698659 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-01 00:12:18.750654 | controller | Collecting py 2025-11-01 00:12:18.754913 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-01 00:12:18.785627 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00 2025-11-01 00:12:18.930587 | controller | Collecting pytest>=3.10 2025-11-01 00:12:18.934588 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-11-01 00:12:18.952892 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 24.1 MB/s eta 0:00:00 2025-11-01 00:12:19.001090 | controller | Collecting iniconfig>=1 2025-11-01 00:12:19.005141 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-01 00:12:19.062852 | controller | Collecting packaging>=20 2025-11-01 00:12:19.066978 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-01 00:12:19.075767 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.7 MB/s eta 0:00:00 2025-11-01 00:12:19.113734 | controller | Collecting pluggy<2,>=1.5 2025-11-01 00:12:19.117889 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-01 00:12:19.181820 | controller | Collecting pygments>=2.7.2 2025-11-01 00:12:19.186412 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-01 00:12:19.210675 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 58.1 MB/s eta 0:00:00 2025-11-01 00:12:19.306267 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-01 00:12:21.266282 | 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-11-01 00:12:21.282455 | controller | 2025-11-01 00:12:21.595429 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-01 00:12:21.595489 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-01 00:12:22.185303 | controller | ok: Runtime: 0:00:03.530797 2025-11-01 00:12:22.196789 | 2025-11-01 00:12:22.196933 | TASK [Update pip] 2025-11-01 00:12:23.484975 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-01 00:12:23.761148 | controller | Collecting pip 2025-11-01 00:12:23.842581 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-01 00:12:23.929278 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 21.8 MB/s eta 0:00:00 2025-11-01 00:12:24.060115 | controller | Installing collected packages: pip 2025-11-01 00:12:24.060360 | controller | Attempting uninstall: pip 2025-11-01 00:12:24.064367 | controller | Found existing installation: pip 22.2.2 2025-11-01 00:12:24.282078 | controller | Uninstalling pip-22.2.2: 2025-11-01 00:12:24.306057 | controller | Successfully uninstalled pip-22.2.2 2025-11-01 00:12:26.134616 | controller | Successfully installed pip-25.3 2025-11-01 00:12:26.607582 | controller | ok: Runtime: 0:00:03.451137 2025-11-01 00:12:26.615234 | 2025-11-01 00:12:26.615322 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-01 00:12:27.450071 | controller | changed 2025-11-01 00:12:27.458240 | 2025-11-01 00:12:27.458370 | TASK [Install ansible into virtualenv] 2025-11-01 00:12:28.617715 | controller | Processing ./src/github.com/ansible/ansible 2025-11-01 00:12:28.622793 | controller | Installing build dependencies: started 2025-11-01 00:12:30.363735 | controller | Installing build dependencies: finished with status 'done' 2025-11-01 00:12:32.089710 | controller | Getting requirements to build wheel: started 2025-11-01 00:12:32.089767 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-01 00:12:33.015279 | controller | Preparing metadata (pyproject.toml): started 2025-11-01 00:12:33.015329 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-01 00:12:33.017409 | 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-11-01 00:12:33.021078 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-01 00:12:33.372372 | controller | ERROR 2025-11-01 00:12:33.372722 | controller | { 2025-11-01 00:12:33.372824 | controller | "delta": "0:00:05.034675", 2025-11-01 00:12:33.372875 | controller | "end": "2025-11-01 00:12:33.167659", 2025-11-01 00:12:33.372915 | controller | "msg": "non-zero return code", 2025-11-01 00:12:33.372980 | controller | "rc": 1, 2025-11-01 00:12:33.373022 | controller | "start": "2025-11-01 00:12:28.132984" 2025-11-01 00:12:33.373059 | controller | } failure 2025-11-01 00:12:33.375512 | 2025-11-01 00:12:33.375596 | PLAY RECAP 2025-11-01 00:12:33.375702 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-01 00:12:33.375759 | 2025-11-01 00:12:33.519729 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-01 00:12:33.520691 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-01 00:12:34.167953 | 2025-11-01 00:12:34.168134 | PLAY [all] 2025-11-01 00:12:34.199145 | 2025-11-01 00:12:34.199287 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-01 00:12:36.031488 | controller | changed: non-zero return code 2025-11-01 00:12:36.037555 | 2025-11-01 00:12:36.037710 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-01 00:12:36.052077 | controller | skipping: Conditional result was False 2025-11-01 00:12:36.058501 | 2025-11-01 00:12:36.058591 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-01 00:12:36.079527 | 2025-11-01 00:12:36.079711 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-01 00:12:36.100639 | 2025-11-01 00:12:36.100835 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-01 00:12:36.115750 | controller | skipping: Conditional result was False 2025-11-01 00:12:36.123585 | 2025-11-01 00:12:36.123709 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-01 00:12:36.145686 | 2025-11-01 00:12:36.145867 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-01 00:12:36.159876 | controller | skipping: Conditional result was False 2025-11-01 00:12:36.167050 | 2025-11-01 00:12:36.167197 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-01 00:12:36.181951 | controller | skipping: Conditional result was False 2025-11-01 00:12:36.189861 | 2025-11-01 00:12:36.189981 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-01 00:12:36.205145 | controller | skipping: Conditional result was False 2025-11-01 00:12:36.234576 | 2025-11-01 00:12:36.234711 | PLAY RECAP 2025-11-01 00:12:36.234763 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-01 00:12:36.234785 | 2025-11-01 00:12:36.351263 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-01 00:12:36.352148 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-01 00:12:37.017653 | 2025-11-01 00:12:37.017798 | PLAY [all:!appliance*] 2025-11-01 00:12:37.040985 | 2025-11-01 00:12:37.041117 | TASK [unregister the node] 2025-11-01 00:12:37.395881 | controller | skipping: Conditional result was False 2025-11-01 00:12:37.406306 | 2025-11-01 00:12:37.406420 | TASK [include_role : fetch-output] 2025-11-01 00:12:37.440003 | controller | ok 2025-11-01 00:12:37.473142 | 2025-11-01 00:12:37.473276 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-01 00:12:37.549083 | controller | skipping: Conditional result was False 2025-11-01 00:12:37.555880 | 2025-11-01 00:12:37.555964 | TASK [fetch-output : Set log path for single node] 2025-11-01 00:12:37.604257 | controller | ok 2025-11-01 00:12:37.618444 | 2025-11-01 00:12:37.618615 | LOOP [fetch-output : Ensure local output dirs] 2025-11-01 00:12:38.042378 | controller -> localhost | ok: "/var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/work/logs" 2025-11-01 00:12:38.293273 | controller -> localhost | changed: "/var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/work/artifacts" 2025-11-01 00:12:38.524052 | controller -> localhost | changed: "/var/lib/zuul/builds/89e0da849a0b4b869de7788416dba9c4/work/docs" 2025-11-01 00:12:38.534601 | 2025-11-01 00:12:38.534752 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-01 00:12:40.776092 | controller | changed: 2025-11-01 00:12:40.776282 | controller | .d..t...... ./ 2025-11-01 00:12:40.776311 | controller | cd+++++++++ controller/ 2025-11-01 00:12:40.776343 | controller | changed: All items complete 2025-11-01 00:12:40.776364 | 2025-11-01 00:12:42.829913 | controller | changed: .d..t...... ./ 2025-11-01 00:12:44.918258 | controller | changed: .d..t...... ./ 2025-11-01 00:12:44.940379 | 2025-11-01 00:12:44.940536 | TASK [include_role : fetch-output-openshift] 2025-11-01 00:12:44.967264 | controller | skipping: Conditional result was False 2025-11-01 00:12:44.978660 | 2025-11-01 00:12:44.978857 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-01 00:12:45.007993 | controller | skipping: Conditional result was False 2025-11-01 00:12:45.016470 | controller | skipping: Conditional result was False 2025-11-01 00:12:45.073061 | 2025-11-01 00:12:45.073176 | PLAY [localhost] 2025-11-01 00:12:45.088016 | 2025-11-01 00:12:45.088119 | TASK [Run Zuul manifest role] 2025-11-01 00:12:45.107771 | localhost | ok 2025-11-01 00:12:45.125820 | 2025-11-01 00:12:45.126069 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-01 00:12:45.533052 | localhost | changed 2025-11-01 00:12:45.538951 | 2025-11-01 00:12:45.539026 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-01 00:12:45.581267 | localhost | ok 2025-11-01 00:12:45.595882 | 2025-11-01 00:12:45.596032 | TASK [Set zuul-log-path fact] 2025-11-01 00:12:45.617404 | localhost | ok 2025-11-01 00:12:45.661376 | 2025-11-01 00:12:45.661491 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-01 00:12:45.702513 | localhost | ok 2025-11-01 00:12:45.714632 | 2025-11-01 00:12:45.714755 | LOOP [Run upload-logs-swift role] 2025-11-01 00:12:45.751830 | localhost | Output suppressed because no_log was given 2025-11-01 00:12:45.788319 | 2025-11-01 00:12:45.788442 | TASK [Set zuul-log-path fact] 2025-11-01 00:12:45.823773 | localhost | skipping: Conditional result was False 2025-11-01 00:12:45.830426 | 2025-11-01 00:12:45.830518 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-01 00:12:46.262555 | localhost -> localhost | ok: Runtime: 0:00:00.006139 2025-11-01 00:12:46.269229 | 2025-11-01 00:12:46.269357 | TASK [upload-logs-swift : Upload logs to swift]