2025-10-15 00:12:01.887338 | Job console starting... 2025-10-15 00:12:01.903406 | Updating repositories 2025-10-15 00:12:02.034039 | Preparing job workspace 2025-10-15 00:12:05.875118 | Running Ansible setup... 2025-10-15 00:12:12.638615 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-15 00:12:13.599931 | 2025-10-15 00:12:13.600080 | PLAY [localhost] 2025-10-15 00:12:13.608958 | 2025-10-15 00:12:13.609033 | TASK [Gathering Facts] 2025-10-15 00:12:15.104503 | localhost | ok 2025-10-15 00:12:15.126574 | 2025-10-15 00:12:15.127216 | TASK [Setup log path fact] 2025-10-15 00:12:15.157957 | localhost | ok 2025-10-15 00:12:15.181134 | 2025-10-15 00:12:15.181227 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-15 00:12:15.245502 | localhost | ok 2025-10-15 00:12:15.261594 | 2025-10-15 00:12:15.261700 | TASK [emit-job-header : Print job information] 2025-10-15 00:12:15.341763 | # Job Information 2025-10-15 00:12:15.342008 | Ansible Version: 2.15.12 2025-10-15 00:12:15.342056 | Job: ansible-test-sanity-docker-milestone 2025-10-15 00:12:15.342080 | Pipeline: periodic 2025-10-15 00:12:15.342099 | Executor: ze02.softwarefactory-project.io 2025-10-15 00:12:15.342117 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-15 00:12:15.342137 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/bdd/ansible/bddac4b4aa2f451187618f335b172bd6/ 2025-10-15 00:12:15.342156 | Event ID: ef49facc7688412789129926cf599d5c 2025-10-15 00:12:15.346313 | 2025-10-15 00:12:15.346383 | LOOP [emit-job-header : Print node information] 2025-10-15 00:12:15.471845 | localhost | ok: 2025-10-15 00:12:15.472052 | localhost | # Node Information 2025-10-15 00:12:15.472079 | localhost | Inventory Hostname: controller 2025-10-15 00:12:15.472099 | localhost | Hostname: ip-172-16-211-203 2025-10-15 00:12:15.472118 | localhost | Username: zuul-worker 2025-10-15 00:12:15.472139 | localhost | Distro: Fedora 37 2025-10-15 00:12:15.472157 | localhost | Provider: ansible-us-east-2 2025-10-15 00:12:15.472174 | localhost | Region: us-east-2 2025-10-15 00:12:15.472190 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-15 00:12:15.472206 | localhost | Product Name: t3.small 2025-10-15 00:12:15.472223 | localhost | Interface IP: 3.145.136.194 2025-10-15 00:12:15.488625 | 2025-10-15 00:12:15.488813 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-15 00:12:16.349567 | localhost -> localhost | changed 2025-10-15 00:12:16.356770 | 2025-10-15 00:12:16.356844 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-15 00:12:17.322010 | localhost -> localhost | changed 2025-10-15 00:12:17.355730 | 2025-10-15 00:12:17.355889 | PLAY [all:!appliance*] 2025-10-15 00:12:17.372484 | 2025-10-15 00:12:17.372571 | TASK [include_role : start-zuul-console] 2025-10-15 00:12:17.403533 | controller | ok 2025-10-15 00:12:17.420347 | 2025-10-15 00:12:17.420490 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-15 00:12:18.139782 | controller | ok 2025-10-15 00:12:18.155980 | 2025-10-15 00:12:18.156113 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-15 00:12:19.883790 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-15 00:12:19.893101 | 2025-10-15 00:12:19.893177 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-15 00:12:20.043857 | controller | skipping: Conditional result was False 2025-10-15 00:12:20.061252 | 2025-10-15 00:12:20.061559 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-15 00:12:20.099259 | controller | skipping: Conditional result was False 2025-10-15 00:12:20.113244 | 2025-10-15 00:12:20.113470 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-15 00:12:20.142235 | controller | skipping: Conditional result was False 2025-10-15 00:12:20.151849 | 2025-10-15 00:12:20.152154 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-15 00:12:20.177743 | controller | skipping: Conditional result was False 2025-10-15 00:12:20.186137 | 2025-10-15 00:12:20.186233 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-15 00:12:20.210424 | controller | skipping: Conditional result was False 2025-10-15 00:12:20.218564 | 2025-10-15 00:12:20.218688 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-15 00:12:20.243053 | controller | skipping: Conditional result was False 2025-10-15 00:12:20.256428 | 2025-10-15 00:12:20.256535 | TASK [Disable Fedora Modular] 2025-10-15 00:12:20.937585 | controller | changed 2025-10-15 00:12:20.952627 | 2025-10-15 00:12:20.952753 | TASK [Enable EPEL] 2025-10-15 00:12:20.981802 | controller | skipping: Conditional result was False 2025-10-15 00:12:20.991640 | 2025-10-15 00:12:20.991773 | TASK [Register the RHEL node] 2025-10-15 00:12:21.154851 | 2025-10-15 00:12:21.155098 | TASK [Show the subscription-manager status] 2025-10-15 00:12:21.340914 | controller | skipping: Conditional result was False 2025-10-15 00:12:21.348867 | 2025-10-15 00:12:21.348936 | TASK [Enable EPEL on RHEL] 2025-10-15 00:12:21.481767 | controller | skipping: Conditional result was False 2025-10-15 00:12:21.489318 | 2025-10-15 00:12:21.489392 | TASK [Install git and tox] 2025-10-15 00:13:50.260839 | controller | changed 2025-10-15 00:13:50.268167 | 2025-10-15 00:13:50.268234 | TASK [include_role : prepare-workspace] 2025-10-15 00:13:50.310264 | controller | ok 2025-10-15 00:13:50.342401 | 2025-10-15 00:13:50.342567 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-15 00:13:50.910006 | controller | ok 2025-10-15 00:13:50.920964 | 2025-10-15 00:13:50.921053 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-15 00:14:04.834619 | controller | Output suppressed because no_log was given 2025-10-15 00:14:04.849063 | 2025-10-15 00:14:04.849156 | TASK [include_role : prepare-workspace-openshift] 2025-10-15 00:14:04.876641 | controller | skipping: Conditional result was False 2025-10-15 00:14:04.940821 | 2025-10-15 00:14:04.940954 | PLAY [all:!appliance] 2025-10-15 00:14:04.956189 | 2025-10-15 00:14:04.956253 | TASK [Run add-build-sshkey role (RSA)] 2025-10-15 00:14:04.987363 | controller | ok 2025-10-15 00:14:05.004259 | 2025-10-15 00:14:05.004338 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-15 00:14:05.236165 | controller -> localhost | ok 2025-10-15 00:14:05.265964 | 2025-10-15 00:14:05.266831 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-15 00:14:05.294279 | controller | ok 2025-10-15 00:14:05.313501 | controller | included: /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-15 00:14:05.321732 | 2025-10-15 00:14:05.321817 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-15 00:14:05.932175 | controller -> localhost | Generating public/private rsa key pair. 2025-10-15 00:14:05.932502 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/work/bddac4b4aa2f451187618f335b172bd6_id_rsa. 2025-10-15 00:14:05.932560 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/work/bddac4b4aa2f451187618f335b172bd6_id_rsa.pub. 2025-10-15 00:14:05.932604 | controller -> localhost | The key fingerprint is: 2025-10-15 00:14:05.932645 | controller -> localhost | SHA256:udNiDXJ8KsgBwvLT3Tnx+OD3IFJq5oc9hRgmwSK6DQU zuul-build-sshkey 2025-10-15 00:14:05.932725 | controller -> localhost | The key's randomart image is: 2025-10-15 00:14:05.932768 | controller -> localhost | +---[RSA 2048]----+ 2025-10-15 00:14:05.932807 | controller -> localhost | |E. . | 2025-10-15 00:14:05.932847 | controller -> localhost | |o o o | 2025-10-15 00:14:05.932886 | controller -> localhost | |++.. . . | 2025-10-15 00:14:05.932924 | controller -> localhost | |+o o..oo * | 2025-10-15 00:14:05.932961 | controller -> localhost | | +o ooooS.o | 2025-10-15 00:14:05.933016 | controller -> localhost | |. .o o.*.@. | 2025-10-15 00:14:05.933066 | controller -> localhost | | o *oO.* | 2025-10-15 00:14:05.933107 | controller -> localhost | | +.++= o | 2025-10-15 00:14:05.933146 | controller -> localhost | | .. . . | 2025-10-15 00:14:05.933191 | controller -> localhost | +----[SHA256]-----+ 2025-10-15 00:14:05.933278 | controller -> localhost | ok: Runtime: 0:00:00.167192 2025-10-15 00:14:05.949495 | 2025-10-15 00:14:05.949801 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-15 00:14:05.995290 | controller | ok 2025-10-15 00:14:06.011770 | controller | included: /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-15 00:14:06.025818 | 2025-10-15 00:14:06.025936 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-15 00:14:06.042486 | controller | skipping: Conditional result was False 2025-10-15 00:14:06.053878 | 2025-10-15 00:14:06.054026 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-15 00:14:06.720843 | controller | changed 2025-10-15 00:14:06.729927 | 2025-10-15 00:14:06.730044 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-15 00:14:07.088640 | controller | ok 2025-10-15 00:14:07.101972 | 2025-10-15 00:14:07.102112 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-15 00:14:08.480658 | controller | changed 2025-10-15 00:14:08.494393 | 2025-10-15 00:14:08.494539 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-15 00:14:09.971129 | controller | changed 2025-10-15 00:14:09.979135 | 2025-10-15 00:14:09.979216 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-15 00:14:10.027395 | controller | skipping: Conditional result was False 2025-10-15 00:14:10.036240 | 2025-10-15 00:14:10.036322 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-15 00:14:10.435133 | controller -> localhost | changed 2025-10-15 00:14:10.447185 | 2025-10-15 00:14:10.447259 | TASK [add-build-sshkey : Add back temp key] 2025-10-15 00:14:10.745630 | controller -> localhost | Identity added: /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/work/bddac4b4aa2f451187618f335b172bd6_id_rsa (zuul-build-sshkey) 2025-10-15 00:14:10.745939 | controller -> localhost | ok: Runtime: 0:00:00.015038 2025-10-15 00:14:10.752424 | 2025-10-15 00:14:10.752487 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-15 00:14:11.291579 | controller | ok 2025-10-15 00:14:11.298637 | 2025-10-15 00:14:11.298732 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-15 00:14:11.334660 | controller | skipping: Conditional result was False 2025-10-15 00:14:11.350103 | 2025-10-15 00:14:11.350190 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-15 00:14:11.384601 | controller | ok 2025-10-15 00:14:11.405980 | 2025-10-15 00:14:11.406070 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-15 00:14:11.707766 | controller -> localhost | ok 2025-10-15 00:14:11.725443 | 2025-10-15 00:14:11.725585 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-15 00:14:11.770946 | controller | ok 2025-10-15 00:14:11.799699 | controller | included: /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-15 00:14:11.814631 | 2025-10-15 00:14:11.814803 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-15 00:14:12.191821 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-15 00:14:12.192325 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/work/bddac4b4aa2f451187618f335b172bd6_id_ecdsa. 2025-10-15 00:14:12.192386 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/work/bddac4b4aa2f451187618f335b172bd6_id_ecdsa.pub. 2025-10-15 00:14:12.192447 | controller -> localhost | The key fingerprint is: 2025-10-15 00:14:12.192490 | controller -> localhost | SHA256:uZoHlV5CiF6EX1HzFcPXBMcSRfUIPhF7Ob6JD493dBI zuul-build-sshkey 2025-10-15 00:14:12.192531 | controller -> localhost | The key's randomart image is: 2025-10-15 00:14:12.192571 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-15 00:14:12.192610 | controller -> localhost | | +...oo +o*OO| 2025-10-15 00:14:12.192692 | controller -> localhost | | o o o + =o==| 2025-10-15 00:14:12.192743 | controller -> localhost | | . o o . = =o.| 2025-10-15 00:14:12.192782 | controller -> localhost | | . . +.. +E. | 2025-10-15 00:14:12.192819 | controller -> localhost | | oSo .. | 2025-10-15 00:14:12.192856 | controller -> localhost | | . .. ..oo| 2025-10-15 00:14:12.192892 | controller -> localhost | | .. o oo.| 2025-10-15 00:14:12.192929 | controller -> localhost | | o. =. .| 2025-10-15 00:14:12.192966 | controller -> localhost | | o. ..o. | 2025-10-15 00:14:12.193002 | controller -> localhost | +----[SHA256]-----+ 2025-10-15 00:14:12.193109 | controller -> localhost | ok: Runtime: 0:00:00.016526 2025-10-15 00:14:12.207502 | 2025-10-15 00:14:12.207635 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-15 00:14:12.248252 | controller | ok 2025-10-15 00:14:12.266750 | controller | included: /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-15 00:14:12.281814 | 2025-10-15 00:14:12.281900 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-15 00:14:12.309895 | controller | skipping: Conditional result was False 2025-10-15 00:14:12.319937 | 2025-10-15 00:14:12.320031 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-15 00:14:12.807446 | controller | changed 2025-10-15 00:14:12.821000 | 2025-10-15 00:14:12.821230 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-15 00:14:13.187729 | controller | ok 2025-10-15 00:14:13.195428 | 2025-10-15 00:14:13.195522 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-15 00:14:14.537185 | controller | changed 2025-10-15 00:14:14.547003 | 2025-10-15 00:14:14.547082 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-15 00:14:15.907733 | controller | changed 2025-10-15 00:14:15.920354 | 2025-10-15 00:14:15.920525 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-15 00:14:15.949553 | controller | skipping: Conditional result was False 2025-10-15 00:14:15.958942 | 2025-10-15 00:14:15.959079 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-15 00:14:16.234730 | controller -> localhost | changed 2025-10-15 00:14:16.249537 | 2025-10-15 00:14:16.249780 | TASK [add-build-sshkey : Add back temp key] 2025-10-15 00:14:16.609048 | controller -> localhost | Identity added: /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/work/bddac4b4aa2f451187618f335b172bd6_id_ecdsa (zuul-build-sshkey) 2025-10-15 00:14:16.609334 | controller -> localhost | ok: Runtime: 0:00:00.014069 2025-10-15 00:14:16.663042 | 2025-10-15 00:14:16.663197 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-15 00:14:17.037783 | controller | ok 2025-10-15 00:14:17.051228 | 2025-10-15 00:14:17.051425 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-15 00:14:17.092430 | controller | skipping: Conditional result was False 2025-10-15 00:14:17.122051 | 2025-10-15 00:14:17.122276 | TASK [include_role : remove-zuul-sshkey] 2025-10-15 00:14:17.151144 | controller | skipping: Conditional result was False 2025-10-15 00:14:17.162059 | 2025-10-15 00:14:17.162191 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-15 00:14:17.522510 | controller | ok: "logs" 2025-10-15 00:14:17.523027 | controller | ok: All items complete 2025-10-15 00:14:17.523089 | 2025-10-15 00:14:17.822268 | controller | ok: "artifacts" 2025-10-15 00:14:18.115278 | controller | ok: "docs" 2025-10-15 00:14:18.142052 | 2025-10-15 00:14:18.142702 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-15 00:14:18.475907 | controller | changed: "logs" 2025-10-15 00:14:18.767451 | controller | changed: "artifacts" 2025-10-15 00:14:19.060495 | controller | changed: "docs" 2025-10-15 00:14:19.112005 | 2025-10-15 00:14:19.112182 | PLAY RECAP 2025-10-15 00:14:19.112251 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-15 00:14:19.112289 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-15 00:14:19.112314 | 2025-10-15 00:14:19.289189 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-15 00:14:19.290852 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-15 00:14:19.903446 | 2025-10-15 00:14:19.903600 | PLAY [all] 2025-10-15 00:14:19.925065 | 2025-10-15 00:14:19.925150 | TASK [Install binary dependencies] 2025-10-15 00:14:19.999195 | controller | ok 2025-10-15 00:14:20.028413 | 2025-10-15 00:14:20.028536 | TASK [bindep : Include find tasks] 2025-10-15 00:14:20.072890 | controller | ok 2025-10-15 00:14:20.085746 | controller | included: /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-15 00:14:20.094235 | 2025-10-15 00:14:20.094350 | TASK [bindep : Look for bindep.txt] 2025-10-15 00:14:20.709947 | controller | ok 2025-10-15 00:14:20.717810 | 2025-10-15 00:14:20.717998 | TASK [bindep : Define bindep_file fact] 2025-10-15 00:14:20.746200 | controller | skipping: Conditional result was False 2025-10-15 00:14:20.759797 | 2025-10-15 00:14:20.759978 | TASK [bindep : Look for other-requirements.txt] 2025-10-15 00:14:21.078545 | controller | ok 2025-10-15 00:14:21.091653 | 2025-10-15 00:14:21.091850 | TASK [bindep : Define bindep_file fact] 2025-10-15 00:14:21.132310 | controller | skipping: Conditional result was False 2025-10-15 00:14:21.147249 | 2025-10-15 00:14:21.147406 | TASK [bindep : Look for bindep fallback file] 2025-10-15 00:14:21.197530 | controller | skipping: Conditional result was False 2025-10-15 00:14:21.212764 | 2025-10-15 00:14:21.212936 | TASK [bindep : Define bindep_file fact] 2025-10-15 00:14:21.258037 | controller | skipping: Conditional result was False 2025-10-15 00:14:21.278607 | 2025-10-15 00:14:21.278921 | TASK [bindep : Include bindep tasks] 2025-10-15 00:14:21.317372 | controller | skipping: Conditional result was False 2025-10-15 00:14:21.332092 | 2025-10-15 00:14:21.332245 | TASK [bindep : Include install tasks] 2025-10-15 00:14:21.371275 | controller | skipping: Conditional result was False 2025-10-15 00:14:21.381765 | 2025-10-15 00:14:21.381905 | LOOP [bindep : Include package tasks] 2025-10-15 00:14:21.451084 | 2025-10-15 00:14:21.451293 | TASK [Run test-setup role] 2025-10-15 00:14:21.472222 | controller | ok 2025-10-15 00:14:21.491885 | 2025-10-15 00:14:21.492044 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-15 00:14:21.836978 | controller | ok 2025-10-15 00:14:21.851648 | 2025-10-15 00:14:21.851881 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-15 00:14:22.001272 | controller | skipping: Conditional result was False 2025-10-15 00:14:22.061701 | 2025-10-15 00:14:22.061887 | PLAY RECAP 2025-10-15 00:14:22.061951 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-15 00:14:22.061983 | 2025-10-15 00:14:22.190121 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-15 00:14:22.191982 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-15 00:14:22.809870 | 2025-10-15 00:14:22.810032 | PLAY [controller] 2025-10-15 00:14:22.829617 | 2025-10-15 00:14:22.829808 | TASK [Create the /root directory] 2025-10-15 00:14:23.615383 | controller | ok 2025-10-15 00:14:23.630467 | 2025-10-15 00:14:23.630657 | TASK [Install glibc-langpack-en] 2025-10-15 00:14:31.691924 | controller | ok: Nothing to do 2025-10-15 00:14:31.699844 | 2025-10-15 00:14:31.699942 | TASK [Ensure controller directory exists] 2025-10-15 00:14:32.181228 | controller | changed 2025-10-15 00:14:32.193748 | 2025-10-15 00:14:32.193887 | TASK [Install container runtime] 2025-10-15 00:14:32.276913 | controller | ok 2025-10-15 00:14:32.337181 | 2025-10-15 00:14:32.337344 | LOOP [ensure-podman : Find distribution installation] 2025-10-15 00:14:32.382264 | controller | ok: "/var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-15 00:14:32.400482 | controller | included: /var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-15 00:14:32.415782 | 2025-10-15 00:14:32.415977 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-15 00:15:50.124905 | controller | changed 2025-10-15 00:15:50.131985 | 2025-10-15 00:15:50.132098 | TASK [ensure-podman : Fetch podman version] 2025-10-15 00:15:50.896057 | controller | Client: Podman Engine 2025-10-15 00:15:50.896137 | controller | Version: 4.6.2 2025-10-15 00:15:50.896167 | controller | API Version: 4.6.2 2025-10-15 00:15:50.896193 | controller | Go Version: go1.19.12 2025-10-15 00:15:50.896230 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-15 00:15:50.896257 | controller | OS/Arch: linux/amd64 2025-10-15 00:15:51.261770 | controller | ok: Runtime: 0:00:00.238267 2025-10-15 00:15:51.273770 | 2025-10-15 00:15:51.273949 | TASK [ensure-podman : Print podman version installed] 2025-10-15 00:15:51.321568 | Podman version: Client: Podman Engine 2025-10-15 00:15:51.321860 | Version: 4.6.2 2025-10-15 00:15:51.321911 | API Version: 4.6.2 2025-10-15 00:15:51.321942 | Go Version: go1.19.12 2025-10-15 00:15:51.321969 | Built: Mon Aug 28 19:38:31 2023 2025-10-15 00:15:51.321997 | OS/Arch: linux/amd64 2025-10-15 00:15:51.327705 | 2025-10-15 00:15:51.327778 | TASK [ensure-podman : Validate podman engine] 2025-10-15 00:15:51.469433 | controller | skipping: Conditional result was False 2025-10-15 00:15:51.483412 | 2025-10-15 00:15:51.483623 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-15 00:15:51.511263 | controller | skipping: Conditional result was False 2025-10-15 00:15:51.535931 | 2025-10-15 00:15:51.536101 | TASK [Ensure python3.8 is present] 2025-10-15 00:15:51.553928 | controller | skipping: Conditional result was False 2025-10-15 00:15:51.568099 | 2025-10-15 00:15:51.568294 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-15 00:15:51.597171 | controller | ok 2025-10-15 00:15:51.630233 | 2025-10-15 00:15:51.630383 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-15 00:15:55.430021 | controller | ok: Nothing to do 2025-10-15 00:15:55.436607 | 2025-10-15 00:15:55.436689 | TASK [our-ensure-python : Also install python3-devel] 2025-10-15 00:16:09.442907 | controller | changed 2025-10-15 00:16:09.459762 | 2025-10-15 00:16:09.459923 | TASK [Run ensure-virtualenv role] 2025-10-15 00:16:09.483424 | controller | ok 2025-10-15 00:16:09.514648 | 2025-10-15 00:16:09.514826 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-15 00:16:09.883987 | controller | /usr/bin/virtualenv 2025-10-15 00:16:10.145793 | controller | ok: Runtime: 0:00:00.004181 2025-10-15 00:16:10.159311 | 2025-10-15 00:16:10.159520 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-15 00:16:10.191550 | controller | skipping: Conditional result was False 2025-10-15 00:16:10.191984 | controller | ok: All items complete 2025-10-15 00:16:10.192014 | 2025-10-15 00:16:10.222653 | 2025-10-15 00:16:10.222952 | TASK [Find the full path of the Python interpreter] 2025-10-15 00:16:10.676126 | controller | /usr/bin/python3 2025-10-15 00:16:10.860181 | controller | ok 2025-10-15 00:16:10.875516 | 2025-10-15 00:16:10.875924 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-15 00:16:12.319968 | controller | created virtual environment CPython3.11.0.final.0-64 in 787ms 2025-10-15 00:16:12.372397 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-15 00:16:12.373056 | 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-15 00:16:12.373122 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-15 00:16:12.373147 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-15 00:16:12.526714 | controller | changed 2025-10-15 00:16:12.539987 | 2025-10-15 00:16:12.540124 | TASK [Set selinux package] 2025-10-15 00:16:12.589252 | controller | ok 2025-10-15 00:16:12.614346 | 2025-10-15 00:16:12.614564 | TASK [Set selinux package (Fedora)] 2025-10-15 00:16:12.666957 | controller | ok 2025-10-15 00:16:12.673452 | 2025-10-15 00:16:12.673533 | TASK [Install selinux into virtualenv] 2025-10-15 00:16:15.250073 | controller | Collecting selinux-please-lie-to-me 2025-10-15 00:16:15.340184 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-15 00:16:15.865226 | controller | Collecting setuptools<50.0.0 2025-10-15 00:16:15.880257 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-15 00:16:15.974985 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 9.0 MB/s eta 0:00:00 2025-10-15 00:16:16.124783 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-15 00:16:16.125197 | controller | Attempting uninstall: setuptools 2025-10-15 00:16:16.130118 | controller | Found existing installation: setuptools 62.6.0 2025-10-15 00:16:16.240411 | controller | Uninstalling setuptools-62.6.0: 2025-10-15 00:16:16.255583 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-15 00:16:17.017830 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-15 00:16:17.227950 | controller | 2025-10-15 00:16:17.443653 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-15 00:16:17.443703 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-15 00:16:17.880470 | controller | ok: Runtime: 0:00:04.291118 2025-10-15 00:16:17.893149 | 2025-10-15 00:16:17.893311 | TASK [Install pytest-forked into virtualenv] 2025-10-15 00:16:19.133254 | controller | Collecting pytest-forked 2025-10-15 00:16:19.221609 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-15 00:16:19.279956 | controller | Collecting py 2025-10-15 00:16:19.293836 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-15 00:16:19.330615 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00 2025-10-15 00:16:19.498644 | controller | Collecting pytest>=3.10 2025-10-15 00:16:19.512746 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-15 00:16:19.577404 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.8 MB/s eta 0:00:00 2025-10-15 00:16:19.631225 | controller | Collecting iniconfig>=1 2025-10-15 00:16:19.645393 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-15 00:16:19.712480 | controller | Collecting packaging>=20 2025-10-15 00:16:19.726497 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-15 00:16:19.739428 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.0 MB/s eta 0:00:00 2025-10-15 00:16:19.786472 | controller | Collecting pluggy<2,>=1.5 2025-10-15 00:16:19.800007 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-15 00:16:19.874639 | controller | Collecting pygments>=2.7.2 2025-10-15 00:16:19.888343 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-15 00:16:20.020422 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.5 MB/s eta 0:00:00 2025-10-15 00:16:20.152747 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-15 00:16:22.410047 | 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-15 00:16:22.425980 | controller | 2025-10-15 00:16:22.608533 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-15 00:16:22.608577 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-15 00:16:23.086894 | controller | ok: Runtime: 0:00:04.203287 2025-10-15 00:16:23.100308 | 2025-10-15 00:16:23.100459 | TASK [Update pip] 2025-10-15 00:16:24.182638 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-15 00:16:24.412661 | controller | Collecting pip 2025-10-15 00:16:24.506843 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-15 00:16:24.667900 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.2 MB/s eta 0:00:00 2025-10-15 00:16:24.817820 | controller | Installing collected packages: pip 2025-10-15 00:16:24.818236 | controller | Attempting uninstall: pip 2025-10-15 00:16:24.822653 | controller | Found existing installation: pip 22.2.2 2025-10-15 00:16:25.077651 | controller | Uninstalling pip-22.2.2: 2025-10-15 00:16:25.108527 | controller | Successfully uninstalled pip-22.2.2 2025-10-15 00:16:26.872416 | controller | Successfully installed pip-25.2 2025-10-15 00:16:27.276058 | controller | ok: Runtime: 0:00:03.479247 2025-10-15 00:16:27.289276 | 2025-10-15 00:16:27.289457 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-15 00:16:27.816144 | controller | changed 2025-10-15 00:16:27.821627 | 2025-10-15 00:16:27.821722 | TASK [Install ansible into virtualenv] 2025-10-15 00:16:28.883709 | controller | Processing ./src/github.com/ansible/ansible 2025-10-15 00:16:28.890200 | controller | Installing build dependencies: started 2025-10-15 00:16:30.804367 | controller | Installing build dependencies: finished with status 'done' 2025-10-15 00:16:30.804657 | controller | Getting requirements to build wheel: started 2025-10-15 00:16:32.316378 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-15 00:16:33.236351 | controller | Preparing metadata (pyproject.toml): started 2025-10-15 00:16:33.236403 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-15 00:16:33.240077 | 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-15 00:16:33.240125 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-15 00:16:33.482647 | controller | ERROR 2025-10-15 00:16:33.482882 | controller | { 2025-10-15 00:16:33.482912 | controller | "delta": "0:00:05.120472", 2025-10-15 00:16:33.482932 | controller | "end": "2025-10-15 00:16:33.388523", 2025-10-15 00:16:33.482950 | controller | "msg": "non-zero return code", 2025-10-15 00:16:33.482987 | controller | "rc": 1, 2025-10-15 00:16:33.483005 | controller | "start": "2025-10-15 00:16:28.268051" 2025-10-15 00:16:33.483021 | controller | } failure 2025-10-15 00:16:33.494325 | 2025-10-15 00:16:33.494488 | PLAY RECAP 2025-10-15 00:16:33.494541 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-15 00:16:33.494562 | 2025-10-15 00:16:33.690521 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-15 00:16:33.691775 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-15 00:16:34.426694 | 2025-10-15 00:16:34.426849 | PLAY [all] 2025-10-15 00:16:34.458159 | 2025-10-15 00:16:34.458268 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-15 00:16:35.272360 | controller | changed: non-zero return code 2025-10-15 00:16:35.283752 | 2025-10-15 00:16:35.283884 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-15 00:16:35.299142 | controller | skipping: Conditional result was False 2025-10-15 00:16:35.308721 | 2025-10-15 00:16:35.308866 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-15 00:16:35.343311 | 2025-10-15 00:16:35.343509 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-15 00:16:35.368368 | 2025-10-15 00:16:35.368646 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-15 00:16:35.410748 | controller | skipping: Conditional result was False 2025-10-15 00:16:35.417153 | 2025-10-15 00:16:35.417240 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-15 00:16:35.449024 | 2025-10-15 00:16:35.449217 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-15 00:16:35.473543 | controller | skipping: Conditional result was False 2025-10-15 00:16:35.483774 | 2025-10-15 00:16:35.483928 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-15 00:16:35.510412 | controller | skipping: Conditional result was False 2025-10-15 00:16:35.522639 | 2025-10-15 00:16:35.522807 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-15 00:16:35.548800 | controller | skipping: Conditional result was False 2025-10-15 00:16:35.579558 | 2025-10-15 00:16:35.579747 | PLAY RECAP 2025-10-15 00:16:35.579805 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-15 00:16:35.579827 | 2025-10-15 00:16:35.710935 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-15 00:16:35.713025 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-15 00:16:36.416777 | 2025-10-15 00:16:36.416910 | PLAY [all:!appliance*] 2025-10-15 00:16:36.452493 | 2025-10-15 00:16:36.452640 | TASK [unregister the node] 2025-10-15 00:16:36.592773 | controller | skipping: Conditional result was False 2025-10-15 00:16:36.602632 | 2025-10-15 00:16:36.602933 | TASK [include_role : fetch-output] 2025-10-15 00:16:36.646645 | controller | ok 2025-10-15 00:16:36.668365 | 2025-10-15 00:16:36.668474 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-15 00:16:36.714032 | controller | skipping: Conditional result was False 2025-10-15 00:16:36.724310 | 2025-10-15 00:16:36.724443 | TASK [fetch-output : Set log path for single node] 2025-10-15 00:16:36.767453 | controller | ok 2025-10-15 00:16:36.773347 | 2025-10-15 00:16:36.773424 | LOOP [fetch-output : Ensure local output dirs] 2025-10-15 00:16:37.247078 | controller -> localhost | ok: "/var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/work/logs" 2025-10-15 00:16:37.458902 | controller -> localhost | changed: "/var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/work/artifacts" 2025-10-15 00:16:37.688046 | controller -> localhost | changed: "/var/lib/zuul/builds/bddac4b4aa2f451187618f335b172bd6/work/docs" 2025-10-15 00:16:37.706409 | 2025-10-15 00:16:37.706583 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-15 00:16:38.988879 | controller | changed: 2025-10-15 00:16:38.992277 | controller | .d..t...... ./ 2025-10-15 00:16:38.992333 | controller | cd+++++++++ controller/ 2025-10-15 00:16:38.992385 | controller | changed: All items complete 2025-10-15 00:16:38.992414 | 2025-10-15 00:16:40.132836 | controller | changed: .d..t...... ./ 2025-10-15 00:16:41.172416 | controller | changed: .d..t...... ./ 2025-10-15 00:16:41.194694 | 2025-10-15 00:16:41.194783 | TASK [include_role : fetch-output-openshift] 2025-10-15 00:16:41.224908 | controller | skipping: Conditional result was False 2025-10-15 00:16:41.247293 | 2025-10-15 00:16:41.247470 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-15 00:16:41.322449 | controller | skipping: Conditional result was False 2025-10-15 00:16:41.337869 | controller | skipping: Conditional result was False 2025-10-15 00:16:41.385496 | 2025-10-15 00:16:41.385705 | PLAY [localhost] 2025-10-15 00:16:41.405931 | 2025-10-15 00:16:41.406033 | TASK [Run Zuul manifest role] 2025-10-15 00:16:41.427598 | localhost | ok 2025-10-15 00:16:41.446603 | 2025-10-15 00:16:41.446729 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-15 00:16:41.872883 | localhost | changed 2025-10-15 00:16:41.877906 | 2025-10-15 00:16:41.878133 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-15 00:16:41.929946 | localhost | ok 2025-10-15 00:16:41.942767 | 2025-10-15 00:16:41.942835 | TASK [Set zuul-log-path fact] 2025-10-15 00:16:41.972491 | localhost | ok 2025-10-15 00:16:41.992096 | 2025-10-15 00:16:41.992170 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-15 00:16:42.075087 | localhost | ok 2025-10-15 00:16:42.086844 | 2025-10-15 00:16:42.087028 | LOOP [Run upload-logs-swift role] 2025-10-15 00:16:42.133833 | localhost | Output suppressed because no_log was given 2025-10-15 00:16:42.162243 | 2025-10-15 00:16:42.162399 | TASK [Set zuul-log-path fact] 2025-10-15 00:16:42.200599 | localhost | skipping: Conditional result was False 2025-10-15 00:16:42.206716 | 2025-10-15 00:16:42.206818 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-15 00:16:42.884650 | localhost -> localhost | ok: Runtime: 0:00:00.024951 2025-10-15 00:16:42.892475 | 2025-10-15 00:16:42.892543 | TASK [upload-logs-swift : Upload logs to swift]