2025-10-07 00:17:08.828457 | Job console starting... 2025-10-07 00:17:08.843564 | Updating repositories 2025-10-07 00:17:09.008010 | Preparing job workspace 2025-10-07 00:17:12.776498 | Running Ansible setup... 2025-10-07 00:17:18.801164 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-07 00:17:19.387113 | 2025-10-07 00:17:19.387231 | PLAY [localhost] 2025-10-07 00:17:19.395558 | 2025-10-07 00:17:19.395630 | TASK [Gathering Facts] 2025-10-07 00:17:20.356257 | localhost | ok 2025-10-07 00:17:20.376962 | 2025-10-07 00:17:20.377117 | TASK [Setup log path fact] 2025-10-07 00:17:20.397205 | localhost | ok 2025-10-07 00:17:20.415570 | 2025-10-07 00:17:20.415715 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-07 00:17:20.445509 | localhost | ok 2025-10-07 00:17:20.456795 | 2025-10-07 00:17:20.456893 | TASK [emit-job-header : Print job information] 2025-10-07 00:17:20.486863 | # Job Information 2025-10-07 00:17:20.487050 | Ansible Version: 2.15.12 2025-10-07 00:17:20.487096 | Job: ansible-test-sanity-docker-milestone 2025-10-07 00:17:20.487129 | Pipeline: periodic 2025-10-07 00:17:20.487158 | Executor: ze02.softwarefactory-project.io 2025-10-07 00:17:20.487185 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-07 00:17:20.487219 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/3a2/ansible/3a2b55da683340d59350dc6c18933806/ 2025-10-07 00:17:20.487247 | Event ID: f91e81a870a84043a9d92fb3c45463b5 2025-10-07 00:17:20.492753 | 2025-10-07 00:17:20.492872 | LOOP [emit-job-header : Print node information] 2025-10-07 00:17:20.593027 | localhost | ok: 2025-10-07 00:17:20.593437 | localhost | # Node Information 2025-10-07 00:17:20.593498 | localhost | Inventory Hostname: controller 2025-10-07 00:17:20.593543 | localhost | Hostname: ip-172-16-3-69 2025-10-07 00:17:20.593584 | localhost | Username: zuul-worker 2025-10-07 00:17:20.593629 | localhost | Distro: Fedora 37 2025-10-07 00:17:20.593998 | localhost | Provider: ansible-us-east-2 2025-10-07 00:17:20.594077 | localhost | Region: us-east-2 2025-10-07 00:17:20.594120 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-07 00:17:20.594158 | localhost | Product Name: t3.small 2025-10-07 00:17:20.594196 | localhost | Interface IP: 18.223.187.130 2025-10-07 00:17:20.616386 | 2025-10-07 00:17:20.616582 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-07 00:17:21.065423 | localhost -> localhost | changed 2025-10-07 00:17:21.071226 | 2025-10-07 00:17:21.071316 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-07 00:17:22.045613 | localhost -> localhost | changed 2025-10-07 00:17:22.075820 | 2025-10-07 00:17:22.075943 | PLAY [all:!appliance*] 2025-10-07 00:17:22.098158 | 2025-10-07 00:17:22.098270 | TASK [include_role : start-zuul-console] 2025-10-07 00:17:22.118161 | controller | ok 2025-10-07 00:17:22.131502 | 2025-10-07 00:17:22.131580 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-07 00:17:22.807195 | controller | ok 2025-10-07 00:17:22.822222 | 2025-10-07 00:17:22.822317 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-07 00:17:24.429302 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-07 00:17:24.439115 | 2025-10-07 00:17:24.439389 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-07 00:17:24.585114 | controller | skipping: Conditional result was False 2025-10-07 00:17:24.599949 | 2025-10-07 00:17:24.600137 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-07 00:17:24.627812 | controller | skipping: Conditional result was False 2025-10-07 00:17:24.641052 | 2025-10-07 00:17:24.641238 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-07 00:17:24.669024 | controller | skipping: Conditional result was False 2025-10-07 00:17:24.677955 | 2025-10-07 00:17:24.678097 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-07 00:17:24.703590 | controller | skipping: Conditional result was False 2025-10-07 00:17:24.713968 | 2025-10-07 00:17:24.714139 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-07 00:17:24.740205 | controller | skipping: Conditional result was False 2025-10-07 00:17:24.748859 | 2025-10-07 00:17:24.749025 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-07 00:17:24.774329 | controller | skipping: Conditional result was False 2025-10-07 00:17:24.791446 | 2025-10-07 00:17:24.791606 | TASK [Disable Fedora Modular] 2025-10-07 00:17:25.680340 | controller | changed 2025-10-07 00:17:25.688257 | 2025-10-07 00:17:25.688345 | TASK [Enable EPEL] 2025-10-07 00:17:25.713209 | controller | skipping: Conditional result was False 2025-10-07 00:17:25.721804 | 2025-10-07 00:17:25.721909 | TASK [Register the RHEL node] 2025-10-07 00:17:25.868256 | 2025-10-07 00:17:25.868444 | TASK [Show the subscription-manager status] 2025-10-07 00:17:26.010487 | controller | skipping: Conditional result was False 2025-10-07 00:17:26.049595 | 2025-10-07 00:17:26.049723 | TASK [Enable EPEL on RHEL] 2025-10-07 00:17:26.192264 | controller | skipping: Conditional result was False 2025-10-07 00:17:26.199064 | 2025-10-07 00:17:26.199151 | TASK [Install git and tox] 2025-10-07 00:19:01.683155 | controller | changed 2025-10-07 00:19:01.692817 | 2025-10-07 00:19:01.693165 | TASK [include_role : prepare-workspace] 2025-10-07 00:19:01.734156 | controller | ok 2025-10-07 00:19:01.792023 | 2025-10-07 00:19:01.792175 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-07 00:19:03.297625 | controller | ok 2025-10-07 00:19:03.312834 | 2025-10-07 00:19:03.313148 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-07 00:19:15.902146 | controller | Output suppressed because no_log was given 2025-10-07 00:19:15.919841 | 2025-10-07 00:19:15.919975 | TASK [include_role : prepare-workspace-openshift] 2025-10-07 00:19:15.949926 | controller | skipping: Conditional result was False 2025-10-07 00:19:15.981764 | 2025-10-07 00:19:15.981894 | PLAY [all:!appliance] 2025-10-07 00:19:16.035554 | 2025-10-07 00:19:16.035677 | TASK [Run add-build-sshkey role (RSA)] 2025-10-07 00:19:16.065714 | controller | ok 2025-10-07 00:19:16.081298 | 2025-10-07 00:19:16.081413 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-07 00:19:16.350029 | controller -> localhost | ok 2025-10-07 00:19:16.363207 | 2025-10-07 00:19:16.363356 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-07 00:19:16.410571 | controller | ok 2025-10-07 00:19:16.435054 | controller | included: /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-07 00:19:16.445592 | 2025-10-07 00:19:16.445754 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-07 00:19:16.889567 | controller -> localhost | Generating public/private rsa key pair. 2025-10-07 00:19:16.889864 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/work/3a2b55da683340d59350dc6c18933806_id_rsa. 2025-10-07 00:19:16.889902 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/work/3a2b55da683340d59350dc6c18933806_id_rsa.pub. 2025-10-07 00:19:16.889932 | controller -> localhost | The key fingerprint is: 2025-10-07 00:19:16.889962 | controller -> localhost | SHA256:pw3+H0zbgpcFdrIV81v1K9DpXw93dvD/UBXcE2hjhjY zuul-build-sshkey 2025-10-07 00:19:16.889990 | controller -> localhost | The key's randomart image is: 2025-10-07 00:19:16.890017 | controller -> localhost | +---[RSA 2048]----+ 2025-10-07 00:19:16.890043 | controller -> localhost | | . =o+| 2025-10-07 00:19:16.890069 | controller -> localhost | | E.*.*=| 2025-10-07 00:19:16.890095 | controller -> localhost | | ..Oo= *| 2025-10-07 00:19:16.890120 | controller -> localhost | | .o* o=| 2025-10-07 00:19:16.890145 | controller -> localhost | | S . ooooO| 2025-10-07 00:19:16.890184 | controller -> localhost | | . = + =o=*| 2025-10-07 00:19:16.890219 | controller -> localhost | | o o B o.o| 2025-10-07 00:19:16.890252 | controller -> localhost | | . . o ..| 2025-10-07 00:19:16.890281 | controller -> localhost | | ... .| 2025-10-07 00:19:16.890313 | controller -> localhost | +----[SHA256]-----+ 2025-10-07 00:19:16.890381 | controller -> localhost | ok: Runtime: 0:00:00.029179 2025-10-07 00:19:16.899828 | 2025-10-07 00:19:16.899969 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-07 00:19:16.932899 | controller | ok 2025-10-07 00:19:16.944569 | controller | included: /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-07 00:19:16.955889 | 2025-10-07 00:19:16.956013 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-07 00:19:16.970813 | controller | skipping: Conditional result was False 2025-10-07 00:19:16.977904 | 2025-10-07 00:19:16.977988 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-07 00:19:17.597919 | controller | changed 2025-10-07 00:19:17.612505 | 2025-10-07 00:19:17.612656 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-07 00:19:17.981157 | controller | ok 2025-10-07 00:19:17.994008 | 2025-10-07 00:19:17.994172 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-07 00:19:19.314966 | controller | changed 2025-10-07 00:19:19.329292 | 2025-10-07 00:19:19.329512 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-07 00:19:20.679747 | controller | changed 2025-10-07 00:19:20.694432 | 2025-10-07 00:19:20.694629 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-07 00:19:20.721718 | controller | skipping: Conditional result was False 2025-10-07 00:19:20.727913 | 2025-10-07 00:19:20.727980 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-07 00:19:21.172618 | controller -> localhost | changed 2025-10-07 00:19:21.184932 | 2025-10-07 00:19:21.185051 | TASK [add-build-sshkey : Add back temp key] 2025-10-07 00:19:21.463574 | controller -> localhost | Identity added: /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/work/3a2b55da683340d59350dc6c18933806_id_rsa (zuul-build-sshkey) 2025-10-07 00:19:21.463773 | controller -> localhost | ok: Runtime: 0:00:00.012598 2025-10-07 00:19:21.470341 | 2025-10-07 00:19:21.470441 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-07 00:19:22.001039 | controller | ok 2025-10-07 00:19:22.006077 | 2025-10-07 00:19:22.006146 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-07 00:19:22.044905 | controller | skipping: Conditional result was False 2025-10-07 00:19:22.055720 | 2025-10-07 00:19:22.055788 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-07 00:19:22.085085 | controller | ok 2025-10-07 00:19:22.109169 | 2025-10-07 00:19:22.109317 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-07 00:19:22.360152 | controller -> localhost | ok 2025-10-07 00:19:22.368619 | 2025-10-07 00:19:22.368757 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-07 00:19:22.391479 | controller | ok 2025-10-07 00:19:22.406976 | controller | included: /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-07 00:19:22.413063 | 2025-10-07 00:19:22.413133 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-07 00:19:22.683608 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-07 00:19:22.684150 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/work/3a2b55da683340d59350dc6c18933806_id_ecdsa. 2025-10-07 00:19:22.684256 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/work/3a2b55da683340d59350dc6c18933806_id_ecdsa.pub. 2025-10-07 00:19:22.684358 | controller -> localhost | The key fingerprint is: 2025-10-07 00:19:22.684440 | controller -> localhost | SHA256:sUzyK2wJMlQKGZxmykw4UELVgRqNZc/95AGgU7/BRlQ zuul-build-sshkey 2025-10-07 00:19:22.684515 | controller -> localhost | The key's randomart image is: 2025-10-07 00:19:22.684591 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-07 00:19:22.684898 | controller -> localhost | |X=B+++++.E | 2025-10-07 00:19:22.685030 | controller -> localhost | |+@.==.= . | 2025-10-07 00:19:22.685117 | controller -> localhost | |B.=o o.*oo | 2025-10-07 00:19:22.685201 | controller -> localhost | |.= . .=*o. | 2025-10-07 00:19:22.685282 | controller -> localhost | | o . .So | 2025-10-07 00:19:22.685364 | controller -> localhost | | o o . . | 2025-10-07 00:19:22.685445 | controller -> localhost | | = . | 2025-10-07 00:19:22.685528 | controller -> localhost | | . . | 2025-10-07 00:19:22.685610 | controller -> localhost | | | 2025-10-07 00:19:22.685740 | controller -> localhost | +----[SHA256]-----+ 2025-10-07 00:19:22.685889 | controller -> localhost | ok: Runtime: 0:00:00.016559 2025-10-07 00:19:22.705771 | 2025-10-07 00:19:22.705991 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-07 00:19:22.745353 | controller | ok 2025-10-07 00:19:22.761412 | controller | included: /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-07 00:19:22.776341 | 2025-10-07 00:19:22.776432 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-07 00:19:22.791779 | controller | skipping: Conditional result was False 2025-10-07 00:19:22.801270 | 2025-10-07 00:19:22.801375 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-07 00:19:23.259525 | controller | changed 2025-10-07 00:19:23.274818 | 2025-10-07 00:19:23.274995 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-07 00:19:23.621478 | controller | ok 2025-10-07 00:19:23.634555 | 2025-10-07 00:19:23.634775 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-07 00:19:24.939011 | controller | changed 2025-10-07 00:19:24.962135 | 2025-10-07 00:19:24.962339 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-07 00:19:26.383233 | controller | changed 2025-10-07 00:19:26.396325 | 2025-10-07 00:19:26.396471 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-07 00:19:26.434271 | controller | skipping: Conditional result was False 2025-10-07 00:19:26.448601 | 2025-10-07 00:19:26.448905 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-07 00:19:26.772381 | controller -> localhost | changed 2025-10-07 00:19:26.815291 | 2025-10-07 00:19:26.815558 | TASK [add-build-sshkey : Add back temp key] 2025-10-07 00:19:27.123600 | controller -> localhost | Identity added: /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/work/3a2b55da683340d59350dc6c18933806_id_ecdsa (zuul-build-sshkey) 2025-10-07 00:19:27.124037 | controller -> localhost | ok: Runtime: 0:00:00.012960 2025-10-07 00:19:27.138228 | 2025-10-07 00:19:27.138392 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-07 00:19:27.523528 | controller | ok 2025-10-07 00:19:27.534997 | 2025-10-07 00:19:27.535132 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-07 00:19:27.573609 | controller | skipping: Conditional result was False 2025-10-07 00:19:27.595756 | 2025-10-07 00:19:27.595923 | TASK [include_role : remove-zuul-sshkey] 2025-10-07 00:19:27.621371 | controller | skipping: Conditional result was False 2025-10-07 00:19:27.667865 | 2025-10-07 00:19:27.667993 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-07 00:19:28.057753 | controller | ok: "logs" 2025-10-07 00:19:28.058220 | controller | ok: All items complete 2025-10-07 00:19:28.058281 | 2025-10-07 00:19:28.425441 | controller | ok: "artifacts" 2025-10-07 00:19:28.714709 | controller | ok: "docs" 2025-10-07 00:19:28.730782 | 2025-10-07 00:19:28.730981 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-07 00:19:29.171541 | controller | changed: "logs" 2025-10-07 00:19:29.529422 | controller | changed: "artifacts" 2025-10-07 00:19:29.823805 | controller | changed: "docs" 2025-10-07 00:19:29.885549 | 2025-10-07 00:19:29.885737 | PLAY RECAP 2025-10-07 00:19:29.885803 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-07 00:19:29.885834 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-07 00:19:29.885855 | 2025-10-07 00:19:30.000184 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-07 00:19:30.001224 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-07 00:19:30.643875 | 2025-10-07 00:19:30.644176 | PLAY [all] 2025-10-07 00:19:30.665250 | 2025-10-07 00:19:30.665352 | TASK [Install binary dependencies] 2025-10-07 00:19:30.737436 | controller | ok 2025-10-07 00:19:30.759852 | 2025-10-07 00:19:30.759991 | TASK [bindep : Include find tasks] 2025-10-07 00:19:30.790484 | controller | ok 2025-10-07 00:19:30.797962 | controller | included: /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-07 00:19:30.804572 | 2025-10-07 00:19:30.804637 | TASK [bindep : Look for bindep.txt] 2025-10-07 00:19:31.339003 | controller | ok 2025-10-07 00:19:31.353929 | 2025-10-07 00:19:31.354098 | TASK [bindep : Define bindep_file fact] 2025-10-07 00:19:31.381935 | controller | skipping: Conditional result was False 2025-10-07 00:19:31.396027 | 2025-10-07 00:19:31.396200 | TASK [bindep : Look for other-requirements.txt] 2025-10-07 00:19:31.701784 | controller | ok 2025-10-07 00:19:31.715515 | 2025-10-07 00:19:31.715705 | TASK [bindep : Define bindep_file fact] 2025-10-07 00:19:31.752337 | controller | skipping: Conditional result was False 2025-10-07 00:19:31.766366 | 2025-10-07 00:19:31.766553 | TASK [bindep : Look for bindep fallback file] 2025-10-07 00:19:31.803919 | controller | skipping: Conditional result was False 2025-10-07 00:19:31.819959 | 2025-10-07 00:19:31.820167 | TASK [bindep : Define bindep_file fact] 2025-10-07 00:19:31.847591 | controller | skipping: Conditional result was False 2025-10-07 00:19:31.862372 | 2025-10-07 00:19:31.862521 | TASK [bindep : Include bindep tasks] 2025-10-07 00:19:31.889690 | controller | skipping: Conditional result was False 2025-10-07 00:19:31.899789 | 2025-10-07 00:19:31.899913 | TASK [bindep : Include install tasks] 2025-10-07 00:19:31.934926 | controller | skipping: Conditional result was False 2025-10-07 00:19:31.944499 | 2025-10-07 00:19:31.944633 | LOOP [bindep : Include package tasks] 2025-10-07 00:19:32.028013 | 2025-10-07 00:19:32.028227 | TASK [Run test-setup role] 2025-10-07 00:19:32.055447 | controller | ok 2025-10-07 00:19:32.079588 | 2025-10-07 00:19:32.079729 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-07 00:19:32.386136 | controller | ok 2025-10-07 00:19:32.394564 | 2025-10-07 00:19:32.394659 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-07 00:19:32.536169 | controller | skipping: Conditional result was False 2025-10-07 00:19:32.573237 | 2025-10-07 00:19:32.573346 | PLAY RECAP 2025-10-07 00:19:32.573416 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-07 00:19:32.573455 | 2025-10-07 00:19:32.676974 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-07 00:19:32.678809 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-07 00:19:33.267899 | 2025-10-07 00:19:33.268054 | PLAY [controller] 2025-10-07 00:19:33.288804 | 2025-10-07 00:19:33.288897 | TASK [Create the /root directory] 2025-10-07 00:19:34.041722 | controller | ok 2025-10-07 00:19:34.054695 | 2025-10-07 00:19:34.054875 | TASK [Install glibc-langpack-en] 2025-10-07 00:19:42.175793 | controller | ok: Nothing to do 2025-10-07 00:19:42.188499 | 2025-10-07 00:19:42.188720 | TASK [Ensure controller directory exists] 2025-10-07 00:19:42.668565 | controller | changed 2025-10-07 00:19:42.681204 | 2025-10-07 00:19:42.681398 | TASK [Install container runtime] 2025-10-07 00:19:42.752315 | controller | ok 2025-10-07 00:19:42.810189 | 2025-10-07 00:19:42.810330 | LOOP [ensure-podman : Find distribution installation] 2025-10-07 00:19:42.847759 | controller | ok: "/var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-07 00:19:42.855990 | controller | included: /var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-07 00:19:42.862687 | 2025-10-07 00:19:42.862758 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-07 00:21:05.358488 | controller | changed 2025-10-07 00:21:05.368243 | 2025-10-07 00:21:05.368378 | TASK [ensure-podman : Fetch podman version] 2025-10-07 00:21:06.182002 | controller | Client: Podman Engine 2025-10-07 00:21:06.182209 | controller | Version: 4.6.2 2025-10-07 00:21:06.182243 | controller | API Version: 4.6.2 2025-10-07 00:21:06.182272 | controller | Go Version: go1.19.12 2025-10-07 00:21:06.182312 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-07 00:21:06.182343 | controller | OS/Arch: linux/amd64 2025-10-07 00:21:06.505152 | controller | ok: Runtime: 0:00:00.254246 2025-10-07 00:21:06.518811 | 2025-10-07 00:21:06.518964 | TASK [ensure-podman : Print podman version installed] 2025-10-07 00:21:06.568064 | Podman version: Client: Podman Engine 2025-10-07 00:21:06.568324 | Version: 4.6.2 2025-10-07 00:21:06.568385 | API Version: 4.6.2 2025-10-07 00:21:06.568429 | Go Version: go1.19.12 2025-10-07 00:21:06.568468 | Built: Mon Aug 28 19:38:31 2023 2025-10-07 00:21:06.568511 | OS/Arch: linux/amd64 2025-10-07 00:21:06.581227 | 2025-10-07 00:21:06.581361 | TASK [ensure-podman : Validate podman engine] 2025-10-07 00:21:06.728535 | controller | skipping: Conditional result was False 2025-10-07 00:21:06.743401 | 2025-10-07 00:21:06.743622 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-07 00:21:06.771284 | controller | skipping: Conditional result was False 2025-10-07 00:21:06.797871 | 2025-10-07 00:21:06.798255 | TASK [Ensure python3.8 is present] 2025-10-07 00:21:06.824481 | controller | skipping: Conditional result was False 2025-10-07 00:21:06.833121 | 2025-10-07 00:21:06.833208 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-07 00:21:06.859224 | controller | ok 2025-10-07 00:21:06.884360 | 2025-10-07 00:21:06.884576 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-07 00:21:10.401447 | controller | ok: Nothing to do 2025-10-07 00:21:10.409960 | 2025-10-07 00:21:10.410070 | TASK [our-ensure-python : Also install python3-devel] 2025-10-07 00:21:23.317178 | controller | changed 2025-10-07 00:21:23.344098 | 2025-10-07 00:21:23.344302 | TASK [Run ensure-virtualenv role] 2025-10-07 00:21:23.383506 | controller | ok 2025-10-07 00:21:23.424079 | 2025-10-07 00:21:23.424253 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-07 00:21:23.822671 | controller | /usr/bin/virtualenv 2025-10-07 00:21:24.063176 | controller | ok: Runtime: 0:00:00.004218 2025-10-07 00:21:24.076298 | 2025-10-07 00:21:24.076526 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-07 00:21:24.112284 | controller | skipping: Conditional result was False 2025-10-07 00:21:24.113078 | controller | ok: All items complete 2025-10-07 00:21:24.113156 | 2025-10-07 00:21:24.189026 | 2025-10-07 00:21:24.189343 | TASK [Find the full path of the Python interpreter] 2025-10-07 00:21:24.620893 | controller | /usr/bin/python3 2025-10-07 00:21:24.825263 | controller | ok 2025-10-07 00:21:24.846825 | 2025-10-07 00:21:24.847624 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-07 00:21:26.278033 | controller | created virtual environment CPython3.11.0.final.0-64 in 775ms 2025-10-07 00:21:26.331658 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-07 00:21:26.331713 | 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-07 00:21:26.331732 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-07 00:21:26.331756 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-07 00:21:26.499495 | controller | changed 2025-10-07 00:21:26.506334 | 2025-10-07 00:21:26.506458 | TASK [Set selinux package] 2025-10-07 00:21:26.533492 | controller | ok 2025-10-07 00:21:26.541349 | 2025-10-07 00:21:26.541441 | TASK [Set selinux package (Fedora)] 2025-10-07 00:21:26.592062 | controller | ok 2025-10-07 00:21:26.603715 | 2025-10-07 00:21:26.603807 | TASK [Install selinux into virtualenv] 2025-10-07 00:21:29.251725 | controller | Collecting selinux-please-lie-to-me 2025-10-07 00:21:29.339623 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-07 00:21:29.862674 | controller | Collecting setuptools<50.0.0 2025-10-07 00:21:29.876394 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-07 00:21:29.998978 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00 2025-10-07 00:21:30.151597 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-07 00:21:30.152039 | controller | Attempting uninstall: setuptools 2025-10-07 00:21:30.157003 | controller | Found existing installation: setuptools 62.6.0 2025-10-07 00:21:30.267840 | controller | Uninstalling setuptools-62.6.0: 2025-10-07 00:21:30.283088 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-07 00:21:31.054843 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-07 00:21:31.259795 | controller | 2025-10-07 00:21:31.475450 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-07 00:21:31.475501 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-07 00:21:31.789605 | controller | ok: Runtime: 0:00:04.388617 2025-10-07 00:21:31.805236 | 2025-10-07 00:21:31.805431 | TASK [Install pytest-forked into virtualenv] 2025-10-07 00:21:33.023044 | controller | Collecting pytest-forked 2025-10-07 00:21:33.110522 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-07 00:21:33.171183 | controller | Collecting py 2025-10-07 00:21:33.188183 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-07 00:21:33.224065 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00 2025-10-07 00:21:33.399594 | controller | Collecting pytest>=3.10 2025-10-07 00:21:33.412389 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-07 00:21:33.470316 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.6 MB/s eta 0:00:00 2025-10-07 00:21:33.527048 | controller | Collecting iniconfig>=1 2025-10-07 00:21:33.539532 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-07 00:21:33.606610 | controller | Collecting packaging>=20 2025-10-07 00:21:33.619213 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-07 00:21:33.631412 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.7 MB/s eta 0:00:00 2025-10-07 00:21:33.678466 | controller | Collecting pluggy<2,>=1.5 2025-10-07 00:21:33.690466 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-07 00:21:33.764170 | controller | Collecting pygments>=2.7.2 2025-10-07 00:21:33.780324 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-07 00:21:33.895438 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.9 MB/s eta 0:00:00 2025-10-07 00:21:34.026656 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-07 00:21:36.320667 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0 2025-10-07 00:21:36.337039 | controller | 2025-10-07 00:21:36.517917 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-07 00:21:36.517969 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-07 00:21:36.972994 | controller | ok: Runtime: 0:00:04.220674 2025-10-07 00:21:36.987145 | 2025-10-07 00:21:36.987355 | TASK [Update pip] 2025-10-07 00:21:38.072604 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-07 00:21:38.368799 | controller | Collecting pip 2025-10-07 00:21:38.458670 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-07 00:21:38.544508 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 21.8 MB/s eta 0:00:00 2025-10-07 00:21:38.700774 | controller | Installing collected packages: pip 2025-10-07 00:21:38.702088 | controller | Attempting uninstall: pip 2025-10-07 00:21:38.708804 | controller | Found existing installation: pip 22.2.2 2025-10-07 00:21:39.005232 | controller | Uninstalling pip-22.2.2: 2025-10-07 00:21:39.035051 | controller | Successfully uninstalled pip-22.2.2 2025-10-07 00:21:40.805062 | controller | Successfully installed pip-25.2 2025-10-07 00:21:41.150505 | controller | ok: Runtime: 0:00:03.530305 2025-10-07 00:21:41.157888 | 2025-10-07 00:21:41.157990 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-07 00:21:41.662434 | controller | changed 2025-10-07 00:21:41.676007 | 2025-10-07 00:21:41.676213 | TASK [Install ansible into virtualenv] 2025-10-07 00:21:42.752531 | controller | Processing ./src/github.com/ansible/ansible 2025-10-07 00:21:42.759058 | controller | Installing build dependencies: started 2025-10-07 00:21:44.726271 | controller | Installing build dependencies: finished with status 'done' 2025-10-07 00:21:44.727384 | controller | Getting requirements to build wheel: started 2025-10-07 00:21:46.363851 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-07 00:21:46.364316 | controller | Preparing metadata (pyproject.toml): started 2025-10-07 00:21:47.288895 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-07 00:21:47.292337 | 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-07 00:21:47.297179 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-07 00:21:47.833876 | controller | ERROR 2025-10-07 00:21:47.834218 | controller | { 2025-10-07 00:21:47.834281 | controller | "delta": "0:00:05.322894", 2025-10-07 00:21:47.834323 | controller | "end": "2025-10-07 00:21:47.448886", 2025-10-07 00:21:47.834360 | controller | "msg": "non-zero return code", 2025-10-07 00:21:47.834414 | controller | "rc": 1, 2025-10-07 00:21:47.834450 | controller | "start": "2025-10-07 00:21:42.125992" 2025-10-07 00:21:47.834483 | controller | } failure 2025-10-07 00:21:47.838307 | 2025-10-07 00:21:47.838426 | PLAY RECAP 2025-10-07 00:21:47.838522 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-07 00:21:47.838575 | 2025-10-07 00:21:47.979549 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-07 00:21:47.981797 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-07 00:21:48.574591 | 2025-10-07 00:21:48.574766 | PLAY [all] 2025-10-07 00:21:48.597564 | 2025-10-07 00:21:48.597802 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-07 00:21:49.393063 | controller | changed: non-zero return code 2025-10-07 00:21:49.407152 | 2025-10-07 00:21:49.407540 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-07 00:21:49.427450 | controller | skipping: Conditional result was False 2025-10-07 00:21:49.441498 | 2025-10-07 00:21:49.441754 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-07 00:21:49.474143 | 2025-10-07 00:21:49.474358 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-07 00:21:49.506357 | 2025-10-07 00:21:49.506553 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-07 00:21:49.521475 | controller | skipping: Conditional result was False 2025-10-07 00:21:49.529051 | 2025-10-07 00:21:49.529172 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-07 00:21:49.564131 | 2025-10-07 00:21:49.564345 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-07 00:21:49.580618 | controller | skipping: Conditional result was False 2025-10-07 00:21:49.588802 | 2025-10-07 00:21:49.588903 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-07 00:21:49.604635 | controller | skipping: Conditional result was False 2025-10-07 00:21:49.613489 | 2025-10-07 00:21:49.613584 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-07 00:21:49.628776 | controller | skipping: Conditional result was False 2025-10-07 00:21:49.663115 | 2025-10-07 00:21:49.663189 | PLAY RECAP 2025-10-07 00:21:49.663226 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-07 00:21:49.663246 | 2025-10-07 00:21:49.756360 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-07 00:21:49.757269 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-07 00:21:50.366073 | 2025-10-07 00:21:50.366268 | PLAY [all:!appliance*] 2025-10-07 00:21:50.388207 | 2025-10-07 00:21:50.388322 | TASK [unregister the node] 2025-10-07 00:21:50.514881 | controller | skipping: Conditional result was False 2025-10-07 00:21:50.521489 | 2025-10-07 00:21:50.521633 | TASK [include_role : fetch-output] 2025-10-07 00:21:50.564019 | controller | ok 2025-10-07 00:21:50.583418 | 2025-10-07 00:21:50.583560 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-07 00:21:50.658739 | controller | skipping: Conditional result was False 2025-10-07 00:21:50.664862 | 2025-10-07 00:21:50.664934 | TASK [fetch-output : Set log path for single node] 2025-10-07 00:21:50.711634 | controller | ok 2025-10-07 00:21:50.723306 | 2025-10-07 00:21:50.723494 | LOOP [fetch-output : Ensure local output dirs] 2025-10-07 00:21:51.186550 | controller -> localhost | ok: "/var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/work/logs" 2025-10-07 00:21:51.479753 | controller -> localhost | changed: "/var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/work/artifacts" 2025-10-07 00:21:51.693099 | controller -> localhost | changed: "/var/lib/zuul/builds/3a2b55da683340d59350dc6c18933806/work/docs" 2025-10-07 00:21:51.719178 | 2025-10-07 00:21:51.719372 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-07 00:21:52.965895 | controller | changed: 2025-10-07 00:21:52.966230 | controller | .d..t...... ./ 2025-10-07 00:21:52.966289 | controller | cd+++++++++ controller/ 2025-10-07 00:21:52.966358 | controller | changed: All items complete 2025-10-07 00:21:52.966403 | 2025-10-07 00:21:53.978733 | controller | changed: .d..t...... ./ 2025-10-07 00:21:54.947948 | controller | changed: .d..t...... ./ 2025-10-07 00:21:54.972060 | 2025-10-07 00:21:54.972527 | TASK [include_role : fetch-output-openshift] 2025-10-07 00:21:54.999118 | controller | skipping: Conditional result was False 2025-10-07 00:21:55.007860 | 2025-10-07 00:21:55.007958 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-07 00:21:55.043309 | controller | skipping: Conditional result was False 2025-10-07 00:21:55.054882 | controller | skipping: Conditional result was False 2025-10-07 00:21:55.117041 | 2025-10-07 00:21:55.117176 | PLAY [localhost] 2025-10-07 00:21:55.136819 | 2025-10-07 00:21:55.136954 | TASK [Run Zuul manifest role] 2025-10-07 00:21:55.159762 | localhost | ok 2025-10-07 00:21:55.188812 | 2025-10-07 00:21:55.189023 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-07 00:21:55.589518 | localhost | changed 2025-10-07 00:21:55.594477 | 2025-10-07 00:21:55.594559 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-07 00:21:55.622772 | localhost | ok 2025-10-07 00:21:55.631421 | 2025-10-07 00:21:55.631497 | TASK [Set zuul-log-path fact] 2025-10-07 00:21:55.650052 | localhost | ok 2025-10-07 00:21:55.663472 | 2025-10-07 00:21:55.663559 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-07 00:21:55.693339 | localhost | ok 2025-10-07 00:21:55.706260 | 2025-10-07 00:21:55.706372 | LOOP [Run upload-logs-swift role] 2025-10-07 00:21:55.729539 | localhost | Output suppressed because no_log was given 2025-10-07 00:21:55.762163 | 2025-10-07 00:21:55.762269 | TASK [Set zuul-log-path fact] 2025-10-07 00:21:55.796831 | localhost | skipping: Conditional result was False 2025-10-07 00:21:55.803851 | 2025-10-07 00:21:55.803955 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-07 00:21:56.278115 | localhost -> localhost | ok: Runtime: 0:00:00.009035 2025-10-07 00:21:56.283724 | 2025-10-07 00:21:56.283793 | TASK [upload-logs-swift : Upload logs to swift]