2025-10-09 00:17:52.818860 | Job console starting... 2025-10-09 00:17:52.834079 | Updating repositories 2025-10-09 00:17:52.985193 | Preparing job workspace 2025-10-09 00:17:56.826005 | Running Ansible setup... 2025-10-09 00:18:03.684800 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-09 00:18:04.420805 | 2025-10-09 00:18:04.421047 | PLAY [localhost] 2025-10-09 00:18:04.433433 | 2025-10-09 00:18:04.433651 | TASK [Gathering Facts] 2025-10-09 00:18:05.677247 | localhost | ok 2025-10-09 00:18:05.693710 | 2025-10-09 00:18:05.693945 | TASK [Setup log path fact] 2025-10-09 00:18:05.714131 | localhost | ok 2025-10-09 00:18:05.730217 | 2025-10-09 00:18:05.730385 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-09 00:18:05.762094 | localhost | ok 2025-10-09 00:18:05.775156 | 2025-10-09 00:18:05.775405 | TASK [emit-job-header : Print job information] 2025-10-09 00:18:05.817757 | # Job Information 2025-10-09 00:18:05.817962 | Ansible Version: 2.15.12 2025-10-09 00:18:05.817994 | Job: ansible-test-sanity-docker-milestone 2025-10-09 00:18:05.818015 | Pipeline: periodic 2025-10-09 00:18:05.818034 | Executor: ze03.softwarefactory-project.io 2025-10-09 00:18:05.818054 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-09 00:18:05.818080 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/d41/ansible/d41ea8faca894761addfaf79478a0cb0/ 2025-10-09 00:18:05.818103 | Event ID: 7e5f5b9352a645a081c4b0c8a3c28952 2025-10-09 00:18:05.822389 | 2025-10-09 00:18:05.822507 | LOOP [emit-job-header : Print node information] 2025-10-09 00:18:05.967227 | localhost | ok: 2025-10-09 00:18:05.967444 | localhost | # Node Information 2025-10-09 00:18:05.967474 | localhost | Inventory Hostname: controller 2025-10-09 00:18:05.967496 | localhost | Hostname: ip-172-16-71-105 2025-10-09 00:18:05.967515 | localhost | Username: zuul-worker 2025-10-09 00:18:05.967536 | localhost | Distro: Fedora 37 2025-10-09 00:18:05.967554 | localhost | Provider: ansible-us-east-2 2025-10-09 00:18:05.967572 | localhost | Region: us-east-2 2025-10-09 00:18:05.967589 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-09 00:18:05.967605 | localhost | Product Name: t3.small 2025-10-09 00:18:05.967622 | localhost | Interface IP: 18.188.228.11 2025-10-09 00:18:05.984386 | 2025-10-09 00:18:05.984592 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-09 00:18:06.513305 | localhost -> localhost | changed 2025-10-09 00:18:06.520085 | 2025-10-09 00:18:06.520202 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-09 00:18:07.671399 | localhost -> localhost | changed 2025-10-09 00:18:07.698245 | 2025-10-09 00:18:07.698390 | PLAY [all:!appliance*] 2025-10-09 00:18:07.726346 | 2025-10-09 00:18:07.726541 | TASK [include_role : start-zuul-console] 2025-10-09 00:18:07.755053 | controller | ok 2025-10-09 00:18:07.782280 | 2025-10-09 00:18:07.782499 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-09 00:18:08.524915 | controller | ok 2025-10-09 00:18:08.550484 | 2025-10-09 00:18:08.550715 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-09 00:18:13.523999 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-09 00:18:13.533721 | 2025-10-09 00:18:13.533882 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-09 00:18:13.685166 | controller | skipping: Conditional result was False 2025-10-09 00:18:13.696116 | 2025-10-09 00:18:13.696303 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-09 00:18:13.723154 | controller | skipping: Conditional result was False 2025-10-09 00:18:13.733673 | 2025-10-09 00:18:13.733886 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-09 00:18:13.761189 | controller | skipping: Conditional result was False 2025-10-09 00:18:13.772563 | 2025-10-09 00:18:13.772917 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-09 00:18:13.801321 | controller | skipping: Conditional result was False 2025-10-09 00:18:13.812384 | 2025-10-09 00:18:13.812967 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-09 00:18:13.840759 | controller | skipping: Conditional result was False 2025-10-09 00:18:13.852573 | 2025-10-09 00:18:13.852820 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-09 00:18:13.881417 | controller | skipping: Conditional result was False 2025-10-09 00:18:13.903962 | 2025-10-09 00:18:13.904145 | TASK [Disable Fedora Modular] 2025-10-09 00:18:14.772669 | controller | changed 2025-10-09 00:18:14.782689 | 2025-10-09 00:18:14.782887 | TASK [Enable EPEL] 2025-10-09 00:18:14.809637 | controller | skipping: Conditional result was False 2025-10-09 00:18:14.819362 | 2025-10-09 00:18:14.819570 | TASK [Register the RHEL node] 2025-10-09 00:18:15.003768 | 2025-10-09 00:18:15.004028 | TASK [Show the subscription-manager status] 2025-10-09 00:18:15.161223 | controller | skipping: Conditional result was False 2025-10-09 00:18:15.169191 | 2025-10-09 00:18:15.169351 | TASK [Enable EPEL on RHEL] 2025-10-09 00:18:15.326306 | controller | skipping: Conditional result was False 2025-10-09 00:18:15.334256 | 2025-10-09 00:18:15.334420 | TASK [Install git and tox] 2025-10-09 00:19:39.181841 | controller | changed 2025-10-09 00:19:39.190373 | 2025-10-09 00:19:39.190571 | TASK [include_role : prepare-workspace] 2025-10-09 00:19:39.223252 | controller | ok 2025-10-09 00:19:39.249139 | 2025-10-09 00:19:39.249324 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-09 00:19:39.775347 | controller | ok 2025-10-09 00:19:39.782550 | 2025-10-09 00:19:39.782625 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-09 00:19:53.050895 | controller | Output suppressed because no_log was given 2025-10-09 00:19:53.069238 | 2025-10-09 00:19:53.069553 | TASK [include_role : prepare-workspace-openshift] 2025-10-09 00:19:53.097009 | controller | skipping: Conditional result was False 2025-10-09 00:19:53.134321 | 2025-10-09 00:19:53.134423 | PLAY [all:!appliance] 2025-10-09 00:19:53.153289 | 2025-10-09 00:19:53.153446 | TASK [Run add-build-sshkey role (RSA)] 2025-10-09 00:19:53.178627 | controller | ok 2025-10-09 00:19:53.257569 | 2025-10-09 00:19:53.257809 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-09 00:19:53.531913 | controller -> localhost | ok 2025-10-09 00:19:53.544146 | 2025-10-09 00:19:53.544344 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-09 00:19:53.582857 | controller | ok 2025-10-09 00:19:53.611070 | controller | included: /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-09 00:19:53.625145 | 2025-10-09 00:19:53.625341 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-09 00:19:54.243752 | controller -> localhost | Generating public/private rsa key pair. 2025-10-09 00:19:54.244050 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/work/d41ea8faca894761addfaf79478a0cb0_id_rsa. 2025-10-09 00:19:54.244091 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/work/d41ea8faca894761addfaf79478a0cb0_id_rsa.pub. 2025-10-09 00:19:54.244136 | controller -> localhost | The key fingerprint is: 2025-10-09 00:19:54.244165 | controller -> localhost | SHA256:roskIauy8WwBiGJ5KiOuSp+FGv9av07O1LXJ8ijaQYQ zuul-build-sshkey 2025-10-09 00:19:54.244193 | controller -> localhost | The key's randomart image is: 2025-10-09 00:19:54.244219 | controller -> localhost | +---[RSA 2048]----+ 2025-10-09 00:19:54.244245 | controller -> localhost | | | 2025-10-09 00:19:54.244288 | controller -> localhost | | . | 2025-10-09 00:19:54.244317 | controller -> localhost | |o . E . | 2025-10-09 00:19:54.244343 | controller -> localhost | |=o . . | 2025-10-09 00:19:54.244368 | controller -> localhost | |+.+ .S . | 2025-10-09 00:19:54.244409 | controller -> localhost | |++... ... o o | 2025-10-09 00:19:54.244445 | controller -> localhost | |*+.o.o +.o + | 2025-10-09 00:19:54.244475 | controller -> localhost | |+=*o+.Bo. + | 2025-10-09 00:19:54.244501 | controller -> localhost | |O+o=+o=Oo. . | 2025-10-09 00:19:54.244530 | controller -> localhost | +----[SHA256]-----+ 2025-10-09 00:19:54.244602 | controller -> localhost | ok: Runtime: 0:00:00.131916 2025-10-09 00:19:54.259673 | 2025-10-09 00:19:54.259909 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-09 00:19:54.297338 | controller | ok 2025-10-09 00:19:54.318953 | controller | included: /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-09 00:19:54.337522 | 2025-10-09 00:19:54.337720 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-09 00:19:54.366284 | controller | skipping: Conditional result was False 2025-10-09 00:19:54.378183 | 2025-10-09 00:19:54.378376 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-09 00:19:55.001721 | controller | changed 2025-10-09 00:19:55.013423 | 2025-10-09 00:19:55.013638 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-09 00:19:55.392958 | controller | ok 2025-10-09 00:19:55.401197 | 2025-10-09 00:19:55.401386 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-09 00:19:56.815189 | controller | changed 2025-10-09 00:19:56.826997 | 2025-10-09 00:19:56.827205 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-09 00:19:58.195746 | controller | changed 2025-10-09 00:19:58.203911 | 2025-10-09 00:19:58.204028 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-09 00:19:58.230337 | controller | skipping: Conditional result was False 2025-10-09 00:19:58.239070 | 2025-10-09 00:19:58.239222 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-09 00:19:58.625661 | controller -> localhost | changed 2025-10-09 00:19:58.639458 | 2025-10-09 00:19:58.639603 | TASK [add-build-sshkey : Add back temp key] 2025-10-09 00:19:58.974379 | controller -> localhost | Identity added: /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/work/d41ea8faca894761addfaf79478a0cb0_id_rsa (zuul-build-sshkey) 2025-10-09 00:19:58.974762 | controller -> localhost | ok: Runtime: 0:00:00.012009 2025-10-09 00:19:58.983170 | 2025-10-09 00:19:58.983264 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-09 00:19:59.541627 | controller | ok 2025-10-09 00:19:59.548370 | 2025-10-09 00:19:59.548527 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-09 00:19:59.573633 | controller | skipping: Conditional result was False 2025-10-09 00:19:59.588181 | 2025-10-09 00:19:59.588581 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-09 00:19:59.614560 | controller | ok 2025-10-09 00:19:59.638270 | 2025-10-09 00:19:59.638471 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-09 00:19:59.909154 | controller -> localhost | ok 2025-10-09 00:19:59.916965 | 2025-10-09 00:19:59.917086 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-09 00:19:59.951039 | controller | ok 2025-10-09 00:19:59.965008 | controller | included: /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-09 00:19:59.973170 | 2025-10-09 00:19:59.973321 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-09 00:20:00.287479 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-09 00:20:00.287799 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/work/d41ea8faca894761addfaf79478a0cb0_id_ecdsa. 2025-10-09 00:20:00.287832 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/work/d41ea8faca894761addfaf79478a0cb0_id_ecdsa.pub. 2025-10-09 00:20:00.287881 | controller -> localhost | The key fingerprint is: 2025-10-09 00:20:00.287924 | controller -> localhost | SHA256:Fo2kmBimJRUbUgdEeGy30bym2Qf/rf1jPvGT/ORio9o zuul-build-sshkey 2025-10-09 00:20:00.287947 | controller -> localhost | The key's randomart image is: 2025-10-09 00:20:00.287976 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-09 00:20:00.288021 | controller -> localhost | |oB%o.o . | 2025-10-09 00:20:00.288049 | controller -> localhost | |.*+*oooo o | 2025-10-09 00:20:00.288073 | controller -> localhost | |.oo.oo..o . | 2025-10-09 00:20:00.288096 | controller -> localhost | | . + . | 2025-10-09 00:20:00.288119 | controller -> localhost | | = oS | 2025-10-09 00:20:00.288141 | controller -> localhost | | o ..o . | 2025-10-09 00:20:00.288163 | controller -> localhost | | . . . .oo| 2025-10-09 00:20:00.288185 | controller -> localhost | | .o. B*.| 2025-10-09 00:20:00.288206 | controller -> localhost | | ooE*o==| 2025-10-09 00:20:00.288229 | controller -> localhost | +----[SHA256]-----+ 2025-10-09 00:20:00.288298 | controller -> localhost | ok: Runtime: 0:00:00.010947 2025-10-09 00:20:00.297116 | 2025-10-09 00:20:00.297306 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-09 00:20:00.330341 | controller | ok 2025-10-09 00:20:00.338623 | controller | included: /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-09 00:20:00.349859 | 2025-10-09 00:20:00.350039 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-09 00:20:00.376134 | controller | skipping: Conditional result was False 2025-10-09 00:20:00.384832 | 2025-10-09 00:20:00.385008 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-09 00:20:00.850670 | controller | changed 2025-10-09 00:20:00.858491 | 2025-10-09 00:20:00.858644 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-09 00:20:01.238419 | controller | ok 2025-10-09 00:20:01.245560 | 2025-10-09 00:20:01.245701 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-09 00:20:02.615833 | controller | changed 2025-10-09 00:20:02.627220 | 2025-10-09 00:20:02.627415 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-09 00:20:04.018450 | controller | changed 2025-10-09 00:20:04.025975 | 2025-10-09 00:20:04.026119 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-09 00:20:04.052809 | controller | skipping: Conditional result was False 2025-10-09 00:20:04.061160 | 2025-10-09 00:20:04.061335 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-09 00:20:04.385945 | controller -> localhost | changed 2025-10-09 00:20:04.401429 | 2025-10-09 00:20:04.401611 | TASK [add-build-sshkey : Add back temp key] 2025-10-09 00:20:04.770513 | controller -> localhost | Identity added: /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/work/d41ea8faca894761addfaf79478a0cb0_id_ecdsa (zuul-build-sshkey) 2025-10-09 00:20:04.770939 | controller -> localhost | ok: Runtime: 0:00:00.011898 2025-10-09 00:20:04.780795 | 2025-10-09 00:20:04.780976 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-09 00:20:05.308957 | controller | ok 2025-10-09 00:20:05.317423 | 2025-10-09 00:20:05.317599 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-09 00:20:05.345015 | controller | skipping: Conditional result was False 2025-10-09 00:20:05.364474 | 2025-10-09 00:20:05.364701 | TASK [include_role : remove-zuul-sshkey] 2025-10-09 00:20:05.391793 | controller | skipping: Conditional result was False 2025-10-09 00:20:05.402759 | 2025-10-09 00:20:05.403092 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-09 00:20:05.873347 | controller | ok: "logs" 2025-10-09 00:20:05.873645 | controller | ok: All items complete 2025-10-09 00:20:05.873678 | 2025-10-09 00:20:06.190070 | controller | ok: "artifacts" 2025-10-09 00:20:06.501814 | controller | ok: "docs" 2025-10-09 00:20:06.513558 | 2025-10-09 00:20:06.514089 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-09 00:20:06.860746 | controller | changed: "logs" 2025-10-09 00:20:07.172416 | controller | changed: "artifacts" 2025-10-09 00:20:07.479225 | controller | changed: "docs" 2025-10-09 00:20:07.527221 | 2025-10-09 00:20:07.527390 | PLAY RECAP 2025-10-09 00:20:07.527456 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-09 00:20:07.527495 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-09 00:20:07.527520 | 2025-10-09 00:20:07.771705 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-09 00:20:07.772796 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-09 00:20:08.459903 | 2025-10-09 00:20:08.460118 | PLAY [all] 2025-10-09 00:20:08.489073 | 2025-10-09 00:20:08.489297 | TASK [Install binary dependencies] 2025-10-09 00:20:08.554821 | controller | ok 2025-10-09 00:20:08.582420 | 2025-10-09 00:20:08.582670 | TASK [bindep : Include find tasks] 2025-10-09 00:20:08.628171 | controller | ok 2025-10-09 00:20:08.643332 | controller | included: /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-09 00:20:08.651840 | 2025-10-09 00:20:08.652047 | TASK [bindep : Look for bindep.txt] 2025-10-09 00:20:09.242030 | controller | ok 2025-10-09 00:20:09.253088 | 2025-10-09 00:20:09.253319 | TASK [bindep : Define bindep_file fact] 2025-10-09 00:20:09.272410 | controller | skipping: Conditional result was False 2025-10-09 00:20:09.283079 | 2025-10-09 00:20:09.283255 | TASK [bindep : Look for other-requirements.txt] 2025-10-09 00:20:09.613659 | controller | ok 2025-10-09 00:20:09.619378 | 2025-10-09 00:20:09.619458 | TASK [bindep : Define bindep_file fact] 2025-10-09 00:20:09.644616 | controller | skipping: Conditional result was False 2025-10-09 00:20:09.653324 | 2025-10-09 00:20:09.653481 | TASK [bindep : Look for bindep fallback file] 2025-10-09 00:20:09.680456 | controller | skipping: Conditional result was False 2025-10-09 00:20:09.695168 | 2025-10-09 00:20:09.695395 | TASK [bindep : Define bindep_file fact] 2025-10-09 00:20:09.722186 | controller | skipping: Conditional result was False 2025-10-09 00:20:09.731036 | 2025-10-09 00:20:09.731230 | TASK [bindep : Include bindep tasks] 2025-10-09 00:20:09.768682 | controller | skipping: Conditional result was False 2025-10-09 00:20:09.778227 | 2025-10-09 00:20:09.778375 | TASK [bindep : Include install tasks] 2025-10-09 00:20:09.803361 | controller | skipping: Conditional result was False 2025-10-09 00:20:09.810850 | 2025-10-09 00:20:09.810988 | LOOP [bindep : Include package tasks] 2025-10-09 00:20:09.880599 | 2025-10-09 00:20:09.880853 | TASK [Run test-setup role] 2025-10-09 00:20:09.902508 | controller | ok 2025-10-09 00:20:09.926670 | 2025-10-09 00:20:09.926879 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-09 00:20:10.278484 | controller | ok 2025-10-09 00:20:10.286783 | 2025-10-09 00:20:10.286955 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-09 00:20:10.436358 | controller | skipping: Conditional result was False 2025-10-09 00:20:10.471241 | 2025-10-09 00:20:10.471434 | PLAY RECAP 2025-10-09 00:20:10.471487 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-09 00:20:10.471509 | 2025-10-09 00:20:10.675002 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-09 00:20:10.676239 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-09 00:20:11.393825 | 2025-10-09 00:20:11.394057 | PLAY [controller] 2025-10-09 00:20:11.420334 | 2025-10-09 00:20:11.420741 | TASK [Create the /root directory] 2025-10-09 00:20:12.196463 | controller | ok 2025-10-09 00:20:12.203269 | 2025-10-09 00:20:12.203407 | TASK [Install glibc-langpack-en] 2025-10-09 00:20:20.287961 | controller | ok: Nothing to do 2025-10-09 00:20:20.294536 | 2025-10-09 00:20:20.294695 | TASK [Ensure controller directory exists] 2025-10-09 00:20:20.696612 | controller | changed 2025-10-09 00:20:20.703906 | 2025-10-09 00:20:20.704089 | TASK [Install container runtime] 2025-10-09 00:20:20.757793 | controller | ok 2025-10-09 00:20:20.799222 | 2025-10-09 00:20:20.799416 | LOOP [ensure-podman : Find distribution installation] 2025-10-09 00:20:20.837605 | controller | ok: "/var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-09 00:20:20.855807 | controller | included: /var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-09 00:20:20.865742 | 2025-10-09 00:20:20.865962 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-09 00:21:33.355664 | controller | changed 2025-10-09 00:21:33.367562 | 2025-10-09 00:21:33.367684 | TASK [ensure-podman : Fetch podman version] 2025-10-09 00:21:34.195904 | controller | Client: Podman Engine 2025-10-09 00:21:34.216635 | controller | Version: 4.6.2 2025-10-09 00:21:34.216735 | controller | API Version: 4.6.2 2025-10-09 00:21:34.216747 | controller | Go Version: go1.19.12 2025-10-09 00:21:34.216770 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-09 00:21:34.216779 | controller | OS/Arch: linux/amd64 2025-10-09 00:21:34.523451 | controller | ok: Runtime: 0:00:00.224483 2025-10-09 00:21:34.534492 | 2025-10-09 00:21:34.534694 | TASK [ensure-podman : Print podman version installed] 2025-10-09 00:21:34.581394 | Podman version: Client: Podman Engine 2025-10-09 00:21:34.581639 | Version: 4.6.2 2025-10-09 00:21:34.581680 | API Version: 4.6.2 2025-10-09 00:21:34.581709 | Go Version: go1.19.12 2025-10-09 00:21:34.581797 | Built: Mon Aug 28 19:38:31 2023 2025-10-09 00:21:34.581835 | OS/Arch: linux/amd64 2025-10-09 00:21:34.592200 | 2025-10-09 00:21:34.592403 | TASK [ensure-podman : Validate podman engine] 2025-10-09 00:21:34.750535 | controller | skipping: Conditional result was False 2025-10-09 00:21:34.769665 | 2025-10-09 00:21:34.770270 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-09 00:21:34.801603 | controller | skipping: Conditional result was False 2025-10-09 00:21:34.821344 | 2025-10-09 00:21:34.821522 | TASK [Ensure python3.8 is present] 2025-10-09 00:21:34.849153 | controller | skipping: Conditional result was False 2025-10-09 00:21:34.859440 | 2025-10-09 00:21:34.859616 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-09 00:21:34.885567 | controller | ok 2025-10-09 00:21:34.909642 | 2025-10-09 00:21:34.910122 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-09 00:21:38.681849 | controller | ok: Nothing to do 2025-10-09 00:21:38.696855 | 2025-10-09 00:21:38.696964 | TASK [our-ensure-python : Also install python3-devel] 2025-10-09 00:21:51.574717 | controller | changed 2025-10-09 00:21:51.593717 | 2025-10-09 00:21:51.593954 | TASK [Run ensure-virtualenv role] 2025-10-09 00:21:51.616983 | controller | ok 2025-10-09 00:21:51.643645 | 2025-10-09 00:21:51.643817 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-09 00:21:52.011873 | controller | /usr/bin/virtualenv 2025-10-09 00:21:52.286838 | controller | ok: Runtime: 0:00:00.004126 2025-10-09 00:21:52.303049 | 2025-10-09 00:21:52.303422 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-09 00:21:52.331817 | controller | skipping: Conditional result was False 2025-10-09 00:21:52.332221 | controller | ok: All items complete 2025-10-09 00:21:52.332258 | 2025-10-09 00:21:52.370120 | 2025-10-09 00:21:52.370334 | TASK [Find the full path of the Python interpreter] 2025-10-09 00:21:52.830756 | controller | /usr/bin/python3 2025-10-09 00:21:53.022528 | controller | ok 2025-10-09 00:21:53.032428 | 2025-10-09 00:21:53.032627 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-09 00:21:54.480975 | controller | created virtual environment CPython3.11.0.final.0-64 in 746ms 2025-10-09 00:21:54.533030 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-09 00:21:54.533674 | 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-09 00:21:54.533699 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-09 00:21:54.533723 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-09 00:21:54.674253 | controller | changed 2025-10-09 00:21:54.687442 | 2025-10-09 00:21:54.687633 | TASK [Set selinux package] 2025-10-09 00:21:54.734247 | controller | ok 2025-10-09 00:21:54.741626 | 2025-10-09 00:21:54.741747 | TASK [Set selinux package (Fedora)] 2025-10-09 00:21:54.790183 | controller | ok 2025-10-09 00:21:54.798551 | 2025-10-09 00:21:54.798651 | TASK [Install selinux into virtualenv] 2025-10-09 00:21:57.458229 | controller | Collecting selinux-please-lie-to-me 2025-10-09 00:21:57.548456 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-09 00:21:58.085966 | controller | Collecting setuptools<50.0.0 2025-10-09 00:21:58.100241 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-09 00:21:58.194166 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 9.0 MB/s eta 0:00:00 2025-10-09 00:21:58.355228 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-09 00:21:58.355522 | controller | Attempting uninstall: setuptools 2025-10-09 00:21:58.360300 | controller | Found existing installation: setuptools 62.6.0 2025-10-09 00:21:58.470892 | controller | Uninstalling setuptools-62.6.0: 2025-10-09 00:21:58.486005 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-09 00:21:59.207416 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-09 00:21:59.430645 | controller | 2025-10-09 00:21:59.653867 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-09 00:21:59.653913 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-09 00:21:59.961318 | controller | ok: Runtime: 0:00:04.357918 2025-10-09 00:21:59.977111 | 2025-10-09 00:21:59.977326 | TASK [Install pytest-forked into virtualenv] 2025-10-09 00:22:01.202179 | controller | Collecting pytest-forked 2025-10-09 00:22:01.290569 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-09 00:22:01.348689 | controller | Collecting py 2025-10-09 00:22:01.361845 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-09 00:22:01.398100 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00 2025-10-09 00:22:01.569196 | controller | Collecting pytest>=3.10 2025-10-09 00:22:01.582597 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-09 00:22:01.647337 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.8 MB/s eta 0:00:00 2025-10-09 00:22:01.702340 | controller | Collecting iniconfig>=1 2025-10-09 00:22:01.715728 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-09 00:22:01.782209 | controller | Collecting packaging>=20 2025-10-09 00:22:01.795430 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-09 00:22:01.808468 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.1 MB/s eta 0:00:00 2025-10-09 00:22:01.855211 | controller | Collecting pluggy<2,>=1.5 2025-10-09 00:22:01.868229 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-09 00:22:01.942301 | controller | Collecting pygments>=2.7.2 2025-10-09 00:22:01.955290 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-09 00:22:02.104690 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 8.4 MB/s eta 0:00:00 2025-10-09 00:22:02.235710 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-09 00:22:04.425419 | 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-09 00:22:04.441215 | controller | 2025-10-09 00:22:04.615229 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-09 00:22:04.615274 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-09 00:22:05.159205 | controller | ok: Runtime: 0:00:04.131116 2025-10-09 00:22:05.178052 | 2025-10-09 00:22:05.178289 | TASK [Update pip] 2025-10-09 00:22:06.309610 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-09 00:22:06.595844 | controller | Collecting pip 2025-10-09 00:22:06.696182 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-09 00:22:06.901337 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.7 MB/s eta 0:00:00 2025-10-09 00:22:07.028315 | controller | Installing collected packages: pip 2025-10-09 00:22:07.028738 | controller | Attempting uninstall: pip 2025-10-09 00:22:07.033051 | controller | Found existing installation: pip 22.2.2 2025-10-09 00:22:07.293228 | controller | Uninstalling pip-22.2.2: 2025-10-09 00:22:07.323208 | controller | Successfully uninstalled pip-22.2.2 2025-10-09 00:22:09.052645 | controller | Successfully installed pip-25.2 2025-10-09 00:22:09.340324 | controller | ok: Runtime: 0:00:03.508556 2025-10-09 00:22:09.351119 | 2025-10-09 00:22:09.351382 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-09 00:22:09.901476 | controller | changed 2025-10-09 00:22:09.910818 | 2025-10-09 00:22:09.910988 | TASK [Install ansible into virtualenv] 2025-10-09 00:22:10.991689 | controller | Processing ./src/github.com/ansible/ansible 2025-10-09 00:22:10.998108 | controller | Installing build dependencies: started 2025-10-09 00:22:12.870211 | controller | Installing build dependencies: finished with status 'done' 2025-10-09 00:22:14.377925 | controller | Getting requirements to build wheel: started 2025-10-09 00:22:14.377993 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-09 00:22:14.380331 | controller | Preparing metadata (pyproject.toml): started 2025-10-09 00:22:15.285207 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-09 00:22:15.288713 | 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-09 00:22:15.288760 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-09 00:22:15.599519 | controller | ERROR 2025-10-09 00:22:15.599886 | controller | { 2025-10-09 00:22:15.599944 | controller | "delta": "0:00:05.051156", 2025-10-09 00:22:15.599982 | controller | "end": "2025-10-09 00:22:15.430974", 2025-10-09 00:22:15.600008 | controller | "msg": "non-zero return code", 2025-10-09 00:22:15.600046 | controller | "rc": 1, 2025-10-09 00:22:15.600071 | controller | "start": "2025-10-09 00:22:10.379818" 2025-10-09 00:22:15.600093 | controller | } failure 2025-10-09 00:22:15.603173 | 2025-10-09 00:22:15.603336 | PLAY RECAP 2025-10-09 00:22:15.603401 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-09 00:22:15.603428 | 2025-10-09 00:22:15.754315 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-09 00:22:15.755830 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-09 00:22:16.455468 | 2025-10-09 00:22:16.455642 | PLAY [all] 2025-10-09 00:22:16.478336 | 2025-10-09 00:22:16.478505 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-09 00:22:17.336488 | controller | changed: non-zero return code 2025-10-09 00:22:17.356720 | 2025-10-09 00:22:17.357000 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-09 00:22:17.384891 | controller | skipping: Conditional result was False 2025-10-09 00:22:17.393378 | 2025-10-09 00:22:17.393499 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-09 00:22:17.440374 | 2025-10-09 00:22:17.440616 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-09 00:22:17.476814 | 2025-10-09 00:22:17.477159 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-09 00:22:17.507666 | controller | skipping: Conditional result was False 2025-10-09 00:22:17.519939 | 2025-10-09 00:22:17.520147 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-09 00:22:17.557907 | 2025-10-09 00:22:17.558290 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-09 00:22:17.591407 | controller | skipping: Conditional result was False 2025-10-09 00:22:17.603644 | 2025-10-09 00:22:17.603871 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-09 00:22:17.635662 | controller | skipping: Conditional result was False 2025-10-09 00:22:17.643416 | 2025-10-09 00:22:17.643561 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-09 00:22:17.669307 | controller | skipping: Conditional result was False 2025-10-09 00:22:17.725692 | 2025-10-09 00:22:17.725825 | PLAY RECAP 2025-10-09 00:22:17.726294 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-09 00:22:17.726329 | 2025-10-09 00:22:17.864026 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-09 00:22:17.865325 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-09 00:22:18.581922 | 2025-10-09 00:22:18.582093 | PLAY [all:!appliance*] 2025-10-09 00:22:18.605817 | 2025-10-09 00:22:18.605980 | TASK [unregister the node] 2025-10-09 00:22:18.749118 | controller | skipping: Conditional result was False 2025-10-09 00:22:18.757727 | 2025-10-09 00:22:18.757928 | TASK [include_role : fetch-output] 2025-10-09 00:22:18.791404 | controller | ok 2025-10-09 00:22:18.818464 | 2025-10-09 00:22:18.818634 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-09 00:22:18.885940 | controller | skipping: Conditional result was False 2025-10-09 00:22:18.897895 | 2025-10-09 00:22:18.898105 | TASK [fetch-output : Set log path for single node] 2025-10-09 00:22:18.951515 | controller | ok 2025-10-09 00:22:18.961256 | 2025-10-09 00:22:18.961412 | LOOP [fetch-output : Ensure local output dirs] 2025-10-09 00:22:19.551918 | controller -> localhost | ok: "/var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/work/logs" 2025-10-09 00:22:19.786782 | controller -> localhost | changed: "/var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/work/artifacts" 2025-10-09 00:22:20.040374 | controller -> localhost | changed: "/var/lib/zuul/builds/d41ea8faca894761addfaf79478a0cb0/work/docs" 2025-10-09 00:22:20.055914 | 2025-10-09 00:22:20.056092 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-09 00:22:21.305615 | controller | changed: 2025-10-09 00:22:21.305919 | controller | .d..t...... ./ 2025-10-09 00:22:21.305959 | controller | cd+++++++++ controller/ 2025-10-09 00:22:21.306009 | controller | changed: All items complete 2025-10-09 00:22:21.306039 | 2025-10-09 00:22:22.409966 | controller | changed: .d..t...... ./ 2025-10-09 00:22:23.543364 | controller | changed: .d..t...... ./ 2025-10-09 00:22:23.562421 | 2025-10-09 00:22:23.562566 | TASK [include_role : fetch-output-openshift] 2025-10-09 00:22:23.601247 | controller | skipping: Conditional result was False 2025-10-09 00:22:23.609585 | 2025-10-09 00:22:23.609753 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-09 00:22:23.650673 | controller | skipping: Conditional result was False 2025-10-09 00:22:23.663420 | controller | skipping: Conditional result was False 2025-10-09 00:22:23.697582 | 2025-10-09 00:22:23.697821 | PLAY [localhost] 2025-10-09 00:22:23.714829 | 2025-10-09 00:22:23.715009 | TASK [Run Zuul manifest role] 2025-10-09 00:22:23.737016 | localhost | ok 2025-10-09 00:22:23.758021 | 2025-10-09 00:22:23.758252 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-09 00:22:24.182162 | localhost | changed 2025-10-09 00:22:24.193333 | 2025-10-09 00:22:24.193773 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-09 00:22:24.233937 | localhost | ok 2025-10-09 00:22:24.252089 | 2025-10-09 00:22:24.253253 | TASK [Set zuul-log-path fact] 2025-10-09 00:22:24.281656 | localhost | ok 2025-10-09 00:22:24.301119 | 2025-10-09 00:22:24.301273 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-09 00:22:24.330760 | localhost | ok 2025-10-09 00:22:24.340657 | 2025-10-09 00:22:24.340786 | LOOP [Run upload-logs-swift role] 2025-10-09 00:22:24.395842 | localhost | Output suppressed because no_log was given 2025-10-09 00:22:24.426793 | 2025-10-09 00:22:24.426940 | TASK [Set zuul-log-path fact] 2025-10-09 00:22:24.452594 | localhost | skipping: Conditional result was False 2025-10-09 00:22:24.459230 | 2025-10-09 00:22:24.459399 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-09 00:22:24.988600 | localhost -> localhost | ok: Runtime: 0:00:00.011260 2025-10-09 00:22:24.997352 | 2025-10-09 00:22:24.997538 | TASK [upload-logs-swift : Upload logs to swift]