2025-11-20 00:25:52.343809 | Job console starting... 2025-11-20 00:25:52.361949 | Updating repositories 2025-11-20 00:25:52.494319 | Preparing job workspace 2025-11-20 00:25:56.855433 | Running Ansible setup... 2025-11-20 00:26:01.556750 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-20 00:26:02.317808 | 2025-11-20 00:26:02.317942 | PLAY [localhost] 2025-11-20 00:26:02.327160 | 2025-11-20 00:26:02.327261 | TASK [Gathering Facts] 2025-11-20 00:26:03.301186 | localhost | ok 2025-11-20 00:26:03.321329 | 2025-11-20 00:26:03.321503 | TASK [Setup log path fact] 2025-11-20 00:26:03.341622 | localhost | ok 2025-11-20 00:26:03.360483 | 2025-11-20 00:26:03.360625 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-20 00:26:03.391913 | localhost | ok 2025-11-20 00:26:03.404548 | 2025-11-20 00:26:03.404752 | TASK [emit-job-header : Print job information] 2025-11-20 00:26:03.455881 | # Job Information 2025-11-20 00:26:03.456047 | Ansible Version: 2.15.12 2025-11-20 00:26:03.456080 | Job: ansible-test-sanity-docker-milestone 2025-11-20 00:26:03.456104 | Pipeline: periodic 2025-11-20 00:26:03.456123 | Executor: ze03.softwarefactory-project.io 2025-11-20 00:26:03.456142 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-20 00:26:03.456163 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/199/ansible/199126248fba4ca49879834e14c4e246/ 2025-11-20 00:26:03.456184 | Event ID: 4015b71040db4124b5e62c0aaaa553e0 2025-11-20 00:26:03.460381 | 2025-11-20 00:26:03.460469 | LOOP [emit-job-header : Print node information] 2025-11-20 00:26:03.595621 | localhost | ok: 2025-11-20 00:26:03.595897 | localhost | # Node Information 2025-11-20 00:26:03.595933 | localhost | Inventory Hostname: controller 2025-11-20 00:26:03.595959 | localhost | Hostname: np0005528758 2025-11-20 00:26:03.595984 | localhost | Username: zuul 2025-11-20 00:26:03.596011 | localhost | Distro: Fedora 37 2025-11-20 00:26:03.596035 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-11-20 00:26:03.596057 | localhost | Region: ca-ymq-1 2025-11-20 00:26:03.596080 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-20 00:26:03.596102 | localhost | Product Name: OpenStack Nova 2025-11-20 00:26:03.596124 | localhost | Interface IP: 162.253.55.58 2025-11-20 00:26:03.616091 | 2025-11-20 00:26:03.616229 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-20 00:26:04.053077 | localhost -> localhost | changed 2025-11-20 00:26:04.058777 | 2025-11-20 00:26:04.058895 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-20 00:26:05.012623 | localhost -> localhost | changed 2025-11-20 00:26:05.036671 | 2025-11-20 00:26:05.036819 | PLAY [all:!appliance*] 2025-11-20 00:26:05.053995 | 2025-11-20 00:26:05.054108 | TASK [include_role : start-zuul-console] 2025-11-20 00:26:05.074833 | controller | ok 2025-11-20 00:26:05.090992 | 2025-11-20 00:26:05.091118 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-20 00:26:05.479057 | controller | ok 2025-11-20 00:26:05.493540 | 2025-11-20 00:26:05.493671 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-20 00:26:06.548545 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-20 00:26:06.558930 | 2025-11-20 00:26:06.559074 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-20 00:26:07.102445 | controller | skipping: Conditional result was False 2025-11-20 00:26:07.110501 | 2025-11-20 00:26:07.110607 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-20 00:26:07.138481 | controller | skipping: Conditional result was False 2025-11-20 00:26:07.146006 | 2025-11-20 00:26:07.146104 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-20 00:26:07.170562 | controller | skipping: Conditional result was False 2025-11-20 00:26:07.178969 | 2025-11-20 00:26:07.179097 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-20 00:26:07.203716 | controller | skipping: Conditional result was False 2025-11-20 00:26:07.214844 | 2025-11-20 00:26:07.215033 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-20 00:26:07.236066 | controller | skipping: Conditional result was False 2025-11-20 00:26:07.248807 | 2025-11-20 00:26:07.250766 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-20 00:26:07.283565 | controller | skipping: Conditional result was False 2025-11-20 00:26:07.315717 | 2025-11-20 00:26:07.315953 | TASK [Disable Fedora Modular] 2025-11-20 00:26:07.575921 | controller | changed 2025-11-20 00:26:07.583262 | 2025-11-20 00:26:07.583407 | TASK [Enable EPEL] 2025-11-20 00:26:07.608473 | controller | skipping: Conditional result was False 2025-11-20 00:26:07.619037 | 2025-11-20 00:26:07.619213 | TASK [Register the RHEL node] 2025-11-20 00:26:08.182011 | 2025-11-20 00:26:08.182303 | TASK [Show the subscription-manager status] 2025-11-20 00:26:08.785276 | controller | skipping: Conditional result was False 2025-11-20 00:26:08.795701 | 2025-11-20 00:26:08.795909 | TASK [Enable EPEL on RHEL] 2025-11-20 00:26:09.352580 | controller | skipping: Conditional result was False 2025-11-20 00:26:09.360951 | 2025-11-20 00:26:09.361069 | TASK [Install git and tox] 2025-11-20 00:27:53.078551 | controller | changed 2025-11-20 00:27:53.087082 | 2025-11-20 00:27:53.088197 | TASK [include_role : prepare-workspace] 2025-11-20 00:27:53.124903 | controller | ok 2025-11-20 00:27:53.158679 | 2025-11-20 00:27:53.158913 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-20 00:27:53.442347 | controller | ok 2025-11-20 00:27:53.454637 | 2025-11-20 00:27:53.454862 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-20 00:28:08.960336 | controller | Output suppressed because no_log was given 2025-11-20 00:28:08.973538 | 2025-11-20 00:28:08.973701 | TASK [include_role : prepare-workspace-openshift] 2025-11-20 00:28:09.001067 | controller | skipping: Conditional result was False 2025-11-20 00:28:09.064925 | 2025-11-20 00:28:09.065035 | PLAY [all:!appliance] 2025-11-20 00:28:09.085408 | 2025-11-20 00:28:09.085530 | TASK [Run add-build-sshkey role (RSA)] 2025-11-20 00:28:09.116813 | controller | ok 2025-11-20 00:28:09.134587 | 2025-11-20 00:28:09.134711 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-20 00:28:09.422457 | controller -> localhost | ok 2025-11-20 00:28:09.433512 | 2025-11-20 00:28:09.433641 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-20 00:28:09.466781 | controller | ok 2025-11-20 00:28:09.487029 | controller | included: /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-20 00:28:09.495255 | 2025-11-20 00:28:09.495386 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-20 00:28:09.998030 | controller -> localhost | Generating public/private rsa key pair. 2025-11-20 00:28:09.998288 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/work/199126248fba4ca49879834e14c4e246_id_rsa. 2025-11-20 00:28:09.998329 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/work/199126248fba4ca49879834e14c4e246_id_rsa.pub. 2025-11-20 00:28:09.998359 | controller -> localhost | The key fingerprint is: 2025-11-20 00:28:09.998387 | controller -> localhost | SHA256:v/Rv0i80Z7vjm7bQAHf5VSyaC1Kc3oHjSFvET4Tk+Hs zuul-build-sshkey 2025-11-20 00:28:09.998414 | controller -> localhost | The key's randomart image is: 2025-11-20 00:28:09.998442 | controller -> localhost | +---[RSA 2048]----+ 2025-11-20 00:28:09.998469 | controller -> localhost | | =o=. ..| 2025-11-20 00:28:09.998496 | controller -> localhost | | .oX o . +| 2025-11-20 00:28:09.998521 | controller -> localhost | | ..B.* = +.| 2025-11-20 00:28:09.998547 | controller -> localhost | | +.+ B . o| 2025-11-20 00:28:09.998571 | controller -> localhost | | S... o .| 2025-11-20 00:28:09.998608 | controller -> localhost | | . .. = o| 2025-11-20 00:28:09.998644 | controller -> localhost | | + E+ =.| 2025-11-20 00:28:09.998672 | controller -> localhost | | . +. =+.| 2025-11-20 00:28:09.998698 | controller -> localhost | | . .++O*| 2025-11-20 00:28:09.998745 | controller -> localhost | +----[SHA256]-----+ 2025-11-20 00:28:09.998830 | controller -> localhost | ok: Runtime: 0:00:00.099977 2025-11-20 00:28:10.008882 | 2025-11-20 00:28:10.008993 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-20 00:28:10.044054 | controller | ok 2025-11-20 00:28:10.061508 | controller | included: /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-20 00:28:10.076283 | 2025-11-20 00:28:10.076406 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-20 00:28:10.100919 | controller | skipping: Conditional result was False 2025-11-20 00:28:10.109698 | 2025-11-20 00:28:10.109836 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-20 00:28:10.577438 | controller | changed 2025-11-20 00:28:10.597836 | 2025-11-20 00:28:10.598154 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-20 00:28:10.848719 | controller | ok 2025-11-20 00:28:10.857355 | 2025-11-20 00:28:10.857489 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-20 00:28:11.505105 | controller | changed 2025-11-20 00:28:11.518613 | 2025-11-20 00:28:11.518892 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-20 00:28:12.120651 | controller | changed 2025-11-20 00:28:12.131783 | 2025-11-20 00:28:12.131940 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-20 00:28:12.160082 | controller | skipping: Conditional result was False 2025-11-20 00:28:12.172575 | 2025-11-20 00:28:12.172779 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-20 00:28:12.631208 | controller -> localhost | changed 2025-11-20 00:28:12.648914 | 2025-11-20 00:28:12.649057 | TASK [add-build-sshkey : Add back temp key] 2025-11-20 00:28:12.986249 | controller -> localhost | Identity added: /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/work/199126248fba4ca49879834e14c4e246_id_rsa (zuul-build-sshkey) 2025-11-20 00:28:12.986600 | controller -> localhost | ok: Runtime: 0:00:00.014828 2025-11-20 00:28:13.000206 | 2025-11-20 00:28:13.000424 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-20 00:28:13.425518 | controller | ok 2025-11-20 00:28:13.435935 | 2025-11-20 00:28:13.436054 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-20 00:28:13.484589 | controller | skipping: Conditional result was False 2025-11-20 00:28:13.504810 | 2025-11-20 00:28:13.504972 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-20 00:28:13.540627 | controller | ok 2025-11-20 00:28:13.564180 | 2025-11-20 00:28:13.564319 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-20 00:28:13.819817 | controller -> localhost | ok 2025-11-20 00:28:13.836368 | 2025-11-20 00:28:13.836552 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-20 00:28:13.862904 | controller | ok 2025-11-20 00:28:13.879876 | controller | included: /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-20 00:28:13.893107 | 2025-11-20 00:28:13.893255 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-20 00:28:14.209180 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-20 00:28:14.209577 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/work/199126248fba4ca49879834e14c4e246_id_ecdsa. 2025-11-20 00:28:14.209643 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/work/199126248fba4ca49879834e14c4e246_id_ecdsa.pub. 2025-11-20 00:28:14.209713 | controller -> localhost | The key fingerprint is: 2025-11-20 00:28:14.209792 | controller -> localhost | SHA256:Q8/jxg8yhNmeg7+AUNHYP1RPxOBQU/ih/zbIPAE/NsU zuul-build-sshkey 2025-11-20 00:28:14.209836 | controller -> localhost | The key's randomart image is: 2025-11-20 00:28:14.209878 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-20 00:28:14.209919 | controller -> localhost | | .+ .o=*+ | 2025-11-20 00:28:14.209959 | controller -> localhost | | ..o .o.+o | 2025-11-20 00:28:14.209998 | controller -> localhost | | . o. .o.o | 2025-11-20 00:28:14.210037 | controller -> localhost | | . =ooo . E | 2025-11-20 00:28:14.210076 | controller -> localhost | | . o S.++ . | 2025-11-20 00:28:14.210115 | controller -> localhost | | . . + = .B | 2025-11-20 00:28:14.210153 | controller -> localhost | | . o * =+ * | 2025-11-20 00:28:14.210191 | controller -> localhost | | o = o= + | 2025-11-20 00:28:14.210230 | controller -> localhost | | o. .o . | 2025-11-20 00:28:14.210269 | controller -> localhost | +----[SHA256]-----+ 2025-11-20 00:28:14.210358 | controller -> localhost | ok: Runtime: 0:00:00.011686 2025-11-20 00:28:14.227120 | 2025-11-20 00:28:14.227388 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-20 00:28:14.267755 | controller | ok 2025-11-20 00:28:14.283296 | controller | included: /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-20 00:28:14.297583 | 2025-11-20 00:28:14.297752 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-20 00:28:14.323206 | controller | skipping: Conditional result was False 2025-11-20 00:28:14.332890 | 2025-11-20 00:28:14.333036 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-20 00:28:14.610894 | controller | changed 2025-11-20 00:28:14.628307 | 2025-11-20 00:28:14.628476 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-20 00:28:14.885163 | controller | ok 2025-11-20 00:28:14.895831 | 2025-11-20 00:28:14.895977 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-20 00:28:15.589806 | controller | changed 2025-11-20 00:28:15.599397 | 2025-11-20 00:28:15.599538 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-20 00:28:16.273224 | controller | changed 2025-11-20 00:28:16.293420 | 2025-11-20 00:28:16.293656 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-20 00:28:16.324374 | controller | skipping: Conditional result was False 2025-11-20 00:28:16.337188 | 2025-11-20 00:28:16.337393 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-20 00:28:16.662548 | controller -> localhost | changed 2025-11-20 00:28:16.712504 | 2025-11-20 00:28:16.712632 | TASK [add-build-sshkey : Add back temp key] 2025-11-20 00:28:17.022984 | controller -> localhost | Identity added: /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/work/199126248fba4ca49879834e14c4e246_id_ecdsa (zuul-build-sshkey) 2025-11-20 00:28:17.023546 | controller -> localhost | ok: Runtime: 0:00:00.011719 2025-11-20 00:28:17.042405 | 2025-11-20 00:28:17.042594 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-20 00:28:17.275131 | controller | ok 2025-11-20 00:28:17.285292 | 2025-11-20 00:28:17.285458 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-20 00:28:17.312637 | controller | skipping: Conditional result was False 2025-11-20 00:28:17.335289 | 2025-11-20 00:28:17.335464 | TASK [include_role : remove-zuul-sshkey] 2025-11-20 00:28:17.352055 | controller | skipping: Conditional result was False 2025-11-20 00:28:17.364335 | 2025-11-20 00:28:17.364496 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-20 00:28:17.616154 | controller | ok: "logs" 2025-11-20 00:28:17.616833 | controller | ok: All items complete 2025-11-20 00:28:17.616908 | 2025-11-20 00:28:17.810102 | controller | ok: "artifacts" 2025-11-20 00:28:18.015356 | controller | ok: "docs" 2025-11-20 00:28:18.025972 | 2025-11-20 00:28:18.026291 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-20 00:28:18.269287 | controller | changed: "logs" 2025-11-20 00:28:18.476504 | controller | changed: "artifacts" 2025-11-20 00:28:18.688530 | controller | changed: "docs" 2025-11-20 00:28:18.733353 | 2025-11-20 00:28:18.733478 | PLAY RECAP 2025-11-20 00:28:18.733538 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-20 00:28:18.733575 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-20 00:28:18.733603 | 2025-11-20 00:28:18.890605 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-20 00:28:18.891985 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-20 00:28:19.545457 | 2025-11-20 00:28:19.545588 | PLAY [all] 2025-11-20 00:28:19.571005 | 2025-11-20 00:28:19.571135 | TASK [Install binary dependencies] 2025-11-20 00:28:19.636902 | controller | ok 2025-11-20 00:28:19.664972 | 2025-11-20 00:28:19.665139 | TASK [bindep : Include find tasks] 2025-11-20 00:28:19.696003 | controller | ok 2025-11-20 00:28:19.705556 | controller | included: /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-20 00:28:19.712329 | 2025-11-20 00:28:19.712404 | TASK [bindep : Look for bindep.txt] 2025-11-20 00:28:20.114356 | controller | ok 2025-11-20 00:28:20.124201 | 2025-11-20 00:28:20.124354 | TASK [bindep : Define bindep_file fact] 2025-11-20 00:28:20.151558 | controller | skipping: Conditional result was False 2025-11-20 00:28:20.162851 | 2025-11-20 00:28:20.163065 | TASK [bindep : Look for other-requirements.txt] 2025-11-20 00:28:20.395225 | controller | ok 2025-11-20 00:28:20.405426 | 2025-11-20 00:28:20.405573 | TASK [bindep : Define bindep_file fact] 2025-11-20 00:28:20.432272 | controller | skipping: Conditional result was False 2025-11-20 00:28:20.443850 | 2025-11-20 00:28:20.444013 | TASK [bindep : Look for bindep fallback file] 2025-11-20 00:28:20.480230 | controller | skipping: Conditional result was False 2025-11-20 00:28:20.489842 | 2025-11-20 00:28:20.490012 | TASK [bindep : Define bindep_file fact] 2025-11-20 00:28:20.516840 | controller | skipping: Conditional result was False 2025-11-20 00:28:20.527403 | 2025-11-20 00:28:20.527545 | TASK [bindep : Include bindep tasks] 2025-11-20 00:28:20.553318 | controller | skipping: Conditional result was False 2025-11-20 00:28:20.563343 | 2025-11-20 00:28:20.563454 | TASK [bindep : Include install tasks] 2025-11-20 00:28:20.589396 | controller | skipping: Conditional result was False 2025-11-20 00:28:20.599064 | 2025-11-20 00:28:20.599214 | LOOP [bindep : Include package tasks] 2025-11-20 00:28:20.684683 | 2025-11-20 00:28:20.685031 | TASK [Run test-setup role] 2025-11-20 00:28:20.715188 | controller | ok 2025-11-20 00:28:20.753754 | 2025-11-20 00:28:20.753905 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-20 00:28:21.001966 | controller | ok 2025-11-20 00:28:21.011518 | 2025-11-20 00:28:21.011611 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-20 00:28:21.554934 | controller | skipping: Conditional result was False 2025-11-20 00:28:21.585877 | 2025-11-20 00:28:21.586044 | PLAY RECAP 2025-11-20 00:28:21.586092 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-20 00:28:21.586115 | 2025-11-20 00:28:21.713802 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-20 00:28:21.715010 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-20 00:28:22.403403 | 2025-11-20 00:28:22.403565 | PLAY [controller] 2025-11-20 00:28:22.426219 | 2025-11-20 00:28:22.426357 | TASK [Create the /root directory] 2025-11-20 00:28:22.869109 | controller | ok 2025-11-20 00:28:22.877816 | 2025-11-20 00:28:22.877902 | TASK [Install glibc-langpack-en] 2025-11-20 00:28:27.154340 | controller | ok: Nothing to do 2025-11-20 00:28:27.162416 | 2025-11-20 00:28:27.162548 | TASK [Ensure controller directory exists] 2025-11-20 00:28:27.387296 | controller | changed 2025-11-20 00:28:27.401434 | 2025-11-20 00:28:27.401612 | TASK [Install container runtime] 2025-11-20 00:28:27.470376 | controller | ok 2025-11-20 00:28:27.530937 | 2025-11-20 00:28:27.531238 | LOOP [ensure-podman : Find distribution installation] 2025-11-20 00:28:27.563265 | controller | ok: "/var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-20 00:28:27.583711 | controller | included: /var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-20 00:28:27.594394 | 2025-11-20 00:28:27.594583 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-20 00:29:35.738908 | controller | changed 2025-11-20 00:29:35.750014 | 2025-11-20 00:29:35.750160 | TASK [ensure-podman : Fetch podman version] 2025-11-20 00:29:36.309613 | controller | Client: Podman Engine 2025-11-20 00:29:36.338008 | controller | Version: 4.6.2 2025-11-20 00:29:36.338165 | controller | API Version: 4.6.2 2025-11-20 00:29:36.338182 | controller | Go Version: go1.19.12 2025-11-20 00:29:36.338209 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-20 00:29:36.338221 | controller | OS/Arch: linux/amd64 2025-11-20 00:29:36.800666 | controller | ok: Runtime: 0:00:00.200680 2025-11-20 00:29:36.808493 | 2025-11-20 00:29:36.808615 | TASK [ensure-podman : Print podman version installed] 2025-11-20 00:29:36.842027 | Podman version: Client: Podman Engine 2025-11-20 00:29:36.842199 | Version: 4.6.2 2025-11-20 00:29:36.842232 | API Version: 4.6.2 2025-11-20 00:29:36.842254 | Go Version: go1.19.12 2025-11-20 00:29:36.842274 | Built: Mon Aug 28 19:38:31 2023 2025-11-20 00:29:36.842294 | OS/Arch: linux/amd64 2025-11-20 00:29:36.849721 | 2025-11-20 00:29:36.849859 | TASK [ensure-podman : Validate podman engine] 2025-11-20 00:29:37.398341 | controller | skipping: Conditional result was False 2025-11-20 00:29:37.405990 | 2025-11-20 00:29:37.406081 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-20 00:29:37.430447 | controller | skipping: Conditional result was False 2025-11-20 00:29:37.444035 | 2025-11-20 00:29:37.444167 | TASK [Ensure python3.8 is present] 2025-11-20 00:29:37.459421 | controller | skipping: Conditional result was False 2025-11-20 00:29:37.467440 | 2025-11-20 00:29:37.467566 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-20 00:29:37.490080 | controller | ok 2025-11-20 00:29:37.516143 | 2025-11-20 00:29:37.516293 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-20 00:29:38.905869 | controller | ok: Nothing to do 2025-11-20 00:29:38.922443 | 2025-11-20 00:29:38.922612 | TASK [our-ensure-python : Also install python3-devel] 2025-11-20 00:29:49.392368 | controller | changed 2025-11-20 00:29:49.411936 | 2025-11-20 00:29:49.412092 | TASK [Run ensure-virtualenv role] 2025-11-20 00:29:49.446896 | controller | ok 2025-11-20 00:29:49.484326 | 2025-11-20 00:29:49.484489 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-20 00:29:49.760684 | controller | /usr/bin/virtualenv 2025-11-20 00:29:50.065865 | controller | ok: Runtime: 0:00:00.004461 2025-11-20 00:29:50.081154 | 2025-11-20 00:29:50.081367 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-20 00:29:50.116237 | controller | skipping: Conditional result was False 2025-11-20 00:29:50.116630 | controller | ok: All items complete 2025-11-20 00:29:50.116673 | 2025-11-20 00:29:50.145166 | 2025-11-20 00:29:50.145385 | TASK [Find the full path of the Python interpreter] 2025-11-20 00:29:50.358829 | controller | /usr/bin/python3 2025-11-20 00:29:50.686878 | controller | ok 2025-11-20 00:29:50.694471 | 2025-11-20 00:29:50.694776 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-20 00:29:51.614956 | controller | created virtual environment CPython3.11.0.final.0-64 in 509ms 2025-11-20 00:29:51.649919 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-20 00:29:51.649960 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv) 2025-11-20 00:29:51.649969 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-20 00:29:51.649984 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-20 00:29:51.738049 | controller | changed 2025-11-20 00:29:51.754848 | 2025-11-20 00:29:51.755043 | TASK [Set selinux package] 2025-11-20 00:29:51.799913 | controller | ok 2025-11-20 00:29:51.814769 | 2025-11-20 00:29:51.814953 | TASK [Set selinux package (Fedora)] 2025-11-20 00:29:51.872942 | controller | ok 2025-11-20 00:29:51.885061 | 2025-11-20 00:29:51.885253 | TASK [Install selinux into virtualenv] 2025-11-20 00:30:17.374509 | controller | Collecting selinux-please-lie-to-me 2025-11-20 00:30:29.672924 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-20 00:30:30.002566 | controller | Collecting setuptools<50.0.0 2025-11-20 00:30:30.092248 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-20 00:30:30.130198 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 23.9 MB/s eta 0:00:00 2025-11-20 00:30:30.212617 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-20 00:30:30.212835 | controller | Attempting uninstall: setuptools 2025-11-20 00:30:30.215198 | controller | Found existing installation: setuptools 62.6.0 2025-11-20 00:30:30.274358 | controller | Uninstalling setuptools-62.6.0: 2025-11-20 00:30:30.282283 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-20 00:30:30.621890 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-20 00:30:50.787862 | controller | 2025-11-20 00:30:50.867541 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-20 00:30:50.867583 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-20 00:30:50.984948 | controller | ok: Runtime: 0:00:58.729425 2025-11-20 00:30:50.995034 | 2025-11-20 00:30:50.995158 | TASK [Install pytest-forked into virtualenv] 2025-11-20 00:31:01.332002 | controller | Collecting pytest-forked 2025-11-20 00:31:13.673979 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-20 00:31:13.812187 | controller | Collecting py 2025-11-20 00:31:13.817555 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-20 00:31:13.842515 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.1 MB/s eta 0:00:00 2025-11-20 00:31:14.072490 | controller | Collecting pytest>=3.10 2025-11-20 00:31:14.117272 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-11-20 00:31:14.132571 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 31.7 MB/s eta 0:00:00 2025-11-20 00:31:14.258249 | controller | Collecting iniconfig>=1.0.1 2025-11-20 00:31:14.299845 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-20 00:31:14.433800 | controller | Collecting packaging>=22 2025-11-20 00:31:14.460121 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-20 00:31:14.473433 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.8 MB/s eta 0:00:00 2025-11-20 00:31:14.549010 | controller | Collecting pluggy<2,>=1.5 2025-11-20 00:31:14.563231 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-20 00:31:14.640969 | controller | Collecting pygments>=2.7.2 2025-11-20 00:31:14.654299 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-20 00:31:14.676320 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 63.4 MB/s eta 0:00:00 2025-11-20 00:31:14.745262 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-20 00:31:15.791809 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.1 pytest-forked-1.6.0 2025-11-20 00:31:15.800740 | controller | 2025-11-20 00:31:15.872141 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-20 00:31:15.872179 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-20 00:31:16.057184 | controller | ok: Runtime: 0:00:24.646689 2025-11-20 00:31:16.064460 | 2025-11-20 00:31:16.065091 | TASK [Update pip] 2025-11-20 00:31:16.574012 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-20 00:31:29.006252 | controller | Collecting pip 2025-11-20 00:31:41.218970 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-20 00:31:41.285479 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 29.2 MB/s eta 0:00:00 2025-11-20 00:31:41.348873 | controller | Installing collected packages: pip 2025-11-20 00:31:41.349026 | controller | Attempting uninstall: pip 2025-11-20 00:31:41.351130 | controller | Found existing installation: pip 22.2.2 2025-11-20 00:31:41.488332 | controller | Uninstalling pip-22.2.2: 2025-11-20 00:31:41.503393 | controller | Successfully uninstalled pip-22.2.2 2025-11-20 00:31:42.300918 | controller | Successfully installed pip-25.3 2025-11-20 00:31:42.614992 | controller | ok: Runtime: 0:00:26.104457 2025-11-20 00:31:42.630917 | 2025-11-20 00:31:42.631112 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-20 00:31:42.860822 | controller | changed 2025-11-20 00:31:42.875776 | 2025-11-20 00:31:42.875970 | TASK [Install ansible into virtualenv] 2025-11-20 00:31:43.438661 | controller | Processing ./src/github.com/ansible/ansible 2025-11-20 00:31:43.441964 | controller | Installing build dependencies: started 2025-11-20 00:32:18.173404 | controller | Installing build dependencies: finished with status 'done' 2025-11-20 00:32:18.174511 | controller | Getting requirements to build wheel: started 2025-11-20 00:32:18.910374 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-20 00:32:18.911724 | controller | Preparing metadata (pyproject.toml): started 2025-11-20 00:32:19.375087 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-20 00:32:19.380519 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-11-20 00:32:19.384013 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-20 00:32:19.495676 | controller | ERROR 2025-11-20 00:32:19.495993 | controller | { 2025-11-20 00:32:19.496059 | controller | "delta": "0:00:36.298569", 2025-11-20 00:32:19.496106 | controller | "end": "2025-11-20 00:32:19.454827", 2025-11-20 00:32:19.496147 | controller | "msg": "non-zero return code", 2025-11-20 00:32:19.496207 | controller | "rc": 1, 2025-11-20 00:32:19.496249 | controller | "start": "2025-11-20 00:31:43.156258" 2025-11-20 00:32:19.496287 | controller | } failure 2025-11-20 00:32:19.499230 | 2025-11-20 00:32:19.499338 | PLAY RECAP 2025-11-20 00:32:19.499428 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-20 00:32:19.499474 | 2025-11-20 00:32:19.644176 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-20 00:32:19.645186 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-20 00:32:20.260312 | 2025-11-20 00:32:20.260452 | PLAY [all] 2025-11-20 00:32:20.284311 | 2025-11-20 00:32:20.284455 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-20 00:32:20.574302 | controller | changed: non-zero return code 2025-11-20 00:32:20.582641 | 2025-11-20 00:32:20.582795 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-20 00:32:20.599516 | controller | skipping: Conditional result was False 2025-11-20 00:32:20.607080 | 2025-11-20 00:32:20.607186 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-20 00:32:20.631137 | 2025-11-20 00:32:20.631322 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-20 00:32:20.655809 | 2025-11-20 00:32:20.655988 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-20 00:32:20.671159 | controller | skipping: Conditional result was False 2025-11-20 00:32:20.680216 | 2025-11-20 00:32:20.680346 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-20 00:32:20.702620 | 2025-11-20 00:32:20.702799 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-20 00:32:20.717868 | controller | skipping: Conditional result was False 2025-11-20 00:32:20.725996 | 2025-11-20 00:32:20.726102 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-20 00:32:20.740544 | controller | skipping: Conditional result was False 2025-11-20 00:32:20.747771 | 2025-11-20 00:32:20.747870 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-20 00:32:20.762760 | controller | skipping: Conditional result was False 2025-11-20 00:32:20.801852 | 2025-11-20 00:32:20.802003 | PLAY RECAP 2025-11-20 00:32:20.802075 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-20 00:32:20.802272 | 2025-11-20 00:32:20.940028 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-20 00:32:20.940928 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-20 00:32:21.633837 | 2025-11-20 00:32:21.634018 | PLAY [all:!appliance*] 2025-11-20 00:32:21.667316 | 2025-11-20 00:32:21.667497 | TASK [unregister the node] 2025-11-20 00:32:22.208979 | controller | skipping: Conditional result was False 2025-11-20 00:32:22.223001 | 2025-11-20 00:32:22.223196 | TASK [include_role : fetch-output] 2025-11-20 00:32:22.259789 | controller | ok 2025-11-20 00:32:22.291094 | 2025-11-20 00:32:22.291258 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-20 00:32:22.337459 | controller | skipping: Conditional result was False 2025-11-20 00:32:22.345202 | 2025-11-20 00:32:22.345300 | TASK [fetch-output : Set log path for single node] 2025-11-20 00:32:22.389080 | controller | ok 2025-11-20 00:32:22.397765 | 2025-11-20 00:32:22.397914 | LOOP [fetch-output : Ensure local output dirs] 2025-11-20 00:32:22.872870 | controller -> localhost | ok: "/var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/work/logs" 2025-11-20 00:32:23.142196 | controller -> localhost | changed: "/var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/work/artifacts" 2025-11-20 00:32:23.376211 | controller -> localhost | changed: "/var/lib/zuul/builds/199126248fba4ca49879834e14c4e246/work/docs" 2025-11-20 00:32:23.392392 | 2025-11-20 00:32:23.392514 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-20 00:32:24.104249 | controller | changed: 2025-11-20 00:32:24.104476 | controller | .d..t...... ./ 2025-11-20 00:32:24.104512 | controller | cd+++++++++ controller/ 2025-11-20 00:32:24.104548 | controller | changed: All items complete 2025-11-20 00:32:24.104568 | 2025-11-20 00:32:24.609512 | controller | changed: .d..t...... ./ 2025-11-20 00:32:25.123659 | controller | changed: .d..t...... ./ 2025-11-20 00:32:25.152091 | 2025-11-20 00:32:25.152249 | TASK [include_role : fetch-output-openshift] 2025-11-20 00:32:25.178039 | controller | skipping: Conditional result was False 2025-11-20 00:32:25.187707 | 2025-11-20 00:32:25.187882 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-20 00:32:25.221234 | controller | skipping: Conditional result was False 2025-11-20 00:32:25.237589 | controller | skipping: Conditional result was False 2025-11-20 00:32:25.282001 | 2025-11-20 00:32:25.282187 | PLAY [localhost] 2025-11-20 00:32:25.297012 | 2025-11-20 00:32:25.297129 | TASK [Run Zuul manifest role] 2025-11-20 00:32:25.316524 | localhost | ok 2025-11-20 00:32:25.333639 | 2025-11-20 00:32:25.333914 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-20 00:32:25.729972 | localhost | changed 2025-11-20 00:32:25.735505 | 2025-11-20 00:32:25.735595 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-20 00:32:25.775656 | localhost | ok 2025-11-20 00:32:25.785248 | 2025-11-20 00:32:25.785383 | TASK [Set zuul-log-path fact] 2025-11-20 00:32:25.804808 | localhost | ok 2025-11-20 00:32:25.819694 | 2025-11-20 00:32:25.819835 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-20 00:32:25.848268 | localhost | ok 2025-11-20 00:32:25.856363 | 2025-11-20 00:32:25.856472 | LOOP [Run upload-logs-swift role] 2025-11-20 00:32:25.891992 | localhost | Output suppressed because no_log was given 2025-11-20 00:32:25.925764 | 2025-11-20 00:32:25.925888 | TASK [Set zuul-log-path fact] 2025-11-20 00:32:25.949997 | localhost | skipping: Conditional result was False 2025-11-20 00:32:25.955268 | 2025-11-20 00:32:25.955346 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-20 00:32:26.451344 | localhost -> localhost | ok: Runtime: 0:00:00.006342 2025-11-20 00:32:26.484935 | 2025-11-20 00:32:26.485052 | TASK [upload-logs-swift : Upload logs to swift]