2025-12-06 00:32:10.461792 | Job console starting... 2025-12-06 00:32:10.473788 | Updating repositories 2025-12-06 00:32:10.633157 | Preparing job workspace 2025-12-06 00:32:14.473619 | Running Ansible setup... 2025-12-06 00:32:22.541935 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-06 00:32:23.175583 | 2025-12-06 00:32:23.175712 | PLAY [localhost] 2025-12-06 00:32:23.184676 | 2025-12-06 00:32:23.184784 | TASK [Gathering Facts] 2025-12-06 00:32:24.199800 | localhost | ok 2025-12-06 00:32:24.231856 | 2025-12-06 00:32:24.232124 | TASK [Setup log path fact] 2025-12-06 00:32:24.259047 | localhost | ok 2025-12-06 00:32:24.286160 | 2025-12-06 00:32:24.286305 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-06 00:32:24.329890 | localhost | ok 2025-12-06 00:32:24.350280 | 2025-12-06 00:32:24.350479 | TASK [emit-job-header : Print job information] 2025-12-06 00:32:24.400996 | # Job Information 2025-12-06 00:32:24.401184 | Ansible Version: 2.15.12 2025-12-06 00:32:24.401217 | Job: ansible-test-sanity-docker-devel 2025-12-06 00:32:24.401238 | Pipeline: periodic 2025-12-06 00:32:24.401257 | Executor: ze01.softwarefactory-project.io 2025-12-06 00:32:24.401276 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-06 00:32:24.401300 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/243/ansible/243494fa224d4771acd1bcedf31c7d4b/ 2025-12-06 00:32:24.401322 | Event ID: a444be38dc2a48ab869f0b68785b4d55 2025-12-06 00:32:24.404987 | 2025-12-06 00:32:24.405070 | LOOP [emit-job-header : Print node information] 2025-12-06 00:32:24.548957 | localhost | ok: 2025-12-06 00:32:24.549183 | localhost | # Node Information 2025-12-06 00:32:24.549212 | localhost | Inventory Hostname: controller 2025-12-06 00:32:24.549232 | localhost | Hostname: np0005548518 2025-12-06 00:32:24.549252 | localhost | Username: zuul 2025-12-06 00:32:24.549276 | localhost | Distro: Fedora 37 2025-12-06 00:32:24.549296 | localhost | Provider: ansible-vexxhost-ams1 2025-12-06 00:32:24.549313 | localhost | Region: ams1 2025-12-06 00:32:24.549331 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-06 00:32:24.549347 | localhost | Product Name: OpenStack Nova 2025-12-06 00:32:24.549364 | localhost | Interface IP: 38.129.16.167 2025-12-06 00:32:24.564330 | 2025-12-06 00:32:24.564492 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-06 00:32:24.979639 | localhost -> localhost | changed 2025-12-06 00:32:24.996507 | 2025-12-06 00:32:24.996656 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-06 00:32:25.908350 | localhost -> localhost | changed 2025-12-06 00:32:25.928335 | 2025-12-06 00:32:25.928416 | PLAY [all:!appliance*] 2025-12-06 00:32:25.945256 | 2025-12-06 00:32:25.945370 | TASK [include_role : start-zuul-console] 2025-12-06 00:32:25.964718 | controller | ok 2025-12-06 00:32:25.979382 | 2025-12-06 00:32:25.979503 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-06 00:32:27.072997 | controller | ok 2025-12-06 00:32:27.100899 | 2025-12-06 00:32:27.101161 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-06 00:32:29.377173 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-06 00:32:29.392786 | 2025-12-06 00:32:29.392925 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-06 00:32:29.772260 | controller | skipping: Conditional result was False 2025-12-06 00:32:29.779497 | 2025-12-06 00:32:29.779573 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-06 00:32:29.803795 | controller | skipping: Conditional result was False 2025-12-06 00:32:29.811077 | 2025-12-06 00:32:29.811213 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-06 00:32:29.825439 | controller | skipping: Conditional result was False 2025-12-06 00:32:29.833192 | 2025-12-06 00:32:29.833316 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-06 00:32:29.857836 | controller | skipping: Conditional result was False 2025-12-06 00:32:29.864259 | 2025-12-06 00:32:29.864340 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-06 00:32:29.888428 | controller | skipping: Conditional result was False 2025-12-06 00:32:29.894999 | 2025-12-06 00:32:29.895125 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-06 00:32:29.909376 | controller | skipping: Conditional result was False 2025-12-06 00:32:29.924036 | 2025-12-06 00:32:29.924174 | TASK [Disable Fedora Modular] 2025-12-06 00:32:31.078177 | controller | changed 2025-12-06 00:32:31.093147 | 2025-12-06 00:32:31.093271 | TASK [Enable EPEL] 2025-12-06 00:32:31.107701 | controller | skipping: Conditional result was False 2025-12-06 00:32:31.116799 | 2025-12-06 00:32:31.116914 | TASK [Register the RHEL node] 2025-12-06 00:32:31.530839 | 2025-12-06 00:32:31.530987 | TASK [Show the subscription-manager status] 2025-12-06 00:32:31.920280 | controller | skipping: Conditional result was False 2025-12-06 00:32:31.935764 | 2025-12-06 00:32:31.935925 | TASK [Enable EPEL on RHEL] 2025-12-06 00:32:32.329564 | controller | skipping: Conditional result was False 2025-12-06 00:32:32.335638 | 2025-12-06 00:32:32.335709 | TASK [Install git and tox] 2025-12-06 00:34:59.353127 | controller | changed 2025-12-06 00:34:59.367958 | 2025-12-06 00:34:59.368289 | TASK [include_role : prepare-workspace] 2025-12-06 00:34:59.398458 | controller | ok 2025-12-06 00:34:59.434878 | 2025-12-06 00:34:59.435177 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-06 00:35:00.294731 | controller | ok 2025-12-06 00:35:00.304924 | 2025-12-06 00:35:00.305040 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-06 00:35:15.643991 | controller | Output suppressed because no_log was given 2025-12-06 00:35:15.660727 | 2025-12-06 00:35:15.660843 | TASK [include_role : prepare-workspace-openshift] 2025-12-06 00:35:15.684442 | controller | skipping: Conditional result was False 2025-12-06 00:35:15.731259 | 2025-12-06 00:35:15.731349 | PLAY [all:!appliance] 2025-12-06 00:35:15.746258 | 2025-12-06 00:35:15.746320 | TASK [Run add-build-sshkey role (RSA)] 2025-12-06 00:35:15.774832 | controller | ok 2025-12-06 00:35:15.789951 | 2025-12-06 00:35:15.790039 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-06 00:35:16.037792 | controller -> localhost | ok 2025-12-06 00:35:16.050106 | 2025-12-06 00:35:16.050245 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-06 00:35:16.086704 | controller | ok 2025-12-06 00:35:16.106450 | controller | included: /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-06 00:35:16.116179 | 2025-12-06 00:35:16.116270 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-06 00:35:16.619129 | controller -> localhost | Generating public/private rsa key pair. 2025-12-06 00:35:16.619336 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/work/243494fa224d4771acd1bcedf31c7d4b_id_rsa. 2025-12-06 00:35:16.619367 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/work/243494fa224d4771acd1bcedf31c7d4b_id_rsa.pub. 2025-12-06 00:35:16.619390 | controller -> localhost | The key fingerprint is: 2025-12-06 00:35:16.619411 | controller -> localhost | SHA256:EpkOtjEBiQGgTc8x1fLzTXqtROW0jvdvRalzM4ZdoNs zuul-build-sshkey 2025-12-06 00:35:16.619431 | controller -> localhost | The key's randomart image is: 2025-12-06 00:35:16.619451 | controller -> localhost | +---[RSA 2048]----+ 2025-12-06 00:35:16.619471 | controller -> localhost | |*ooo+... | 2025-12-06 00:35:16.619490 | controller -> localhost | |oo.o +.o. + | 2025-12-06 00:35:16.619509 | controller -> localhost | |. . B +o = o.| 2025-12-06 00:35:16.619528 | controller -> localhost | | . * .o + o.o| 2025-12-06 00:35:16.619546 | controller -> localhost | | . o So = *+..| 2025-12-06 00:35:16.619572 | controller -> localhost | | . o *+E*.| 2025-12-06 00:35:16.619597 | controller -> localhost | | o o+.+| 2025-12-06 00:35:16.619618 | controller -> localhost | | . o| 2025-12-06 00:35:16.619638 | controller -> localhost | | .o| 2025-12-06 00:35:16.619659 | controller -> localhost | +----[SHA256]-----+ 2025-12-06 00:35:16.619709 | controller -> localhost | ok: Runtime: 0:00:00.112673 2025-12-06 00:35:16.626673 | 2025-12-06 00:35:16.626757 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-06 00:35:16.645325 | controller | ok 2025-12-06 00:35:16.654792 | controller | included: /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-06 00:35:16.663478 | 2025-12-06 00:35:16.663540 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-06 00:35:16.686937 | controller | skipping: Conditional result was False 2025-12-06 00:35:16.694383 | 2025-12-06 00:35:16.694468 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-06 00:35:17.750488 | controller | changed 2025-12-06 00:35:17.763880 | 2025-12-06 00:35:17.764056 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-06 00:35:18.424992 | controller | ok 2025-12-06 00:35:18.439473 | 2025-12-06 00:35:18.439610 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-06 00:35:21.455574 | controller | changed 2025-12-06 00:35:21.468827 | 2025-12-06 00:35:21.468986 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-06 00:35:24.511612 | controller | changed 2025-12-06 00:35:24.518129 | 2025-12-06 00:35:24.518208 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-06 00:35:24.543370 | controller | skipping: Conditional result was False 2025-12-06 00:35:24.551372 | 2025-12-06 00:35:24.551478 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-06 00:35:25.016766 | controller -> localhost | changed 2025-12-06 00:35:25.043841 | 2025-12-06 00:35:25.044001 | TASK [add-build-sshkey : Add back temp key] 2025-12-06 00:35:25.409081 | controller -> localhost | Identity added: /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/work/243494fa224d4771acd1bcedf31c7d4b_id_rsa (zuul-build-sshkey) 2025-12-06 00:35:25.409501 | controller -> localhost | ok: Runtime: 0:00:00.015752 2025-12-06 00:35:25.428847 | 2025-12-06 00:35:25.429011 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-06 00:35:26.384444 | controller | ok 2025-12-06 00:35:26.392337 | 2025-12-06 00:35:26.392428 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-06 00:35:26.428196 | controller | skipping: Conditional result was False 2025-12-06 00:35:26.444472 | 2025-12-06 00:35:26.444594 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-06 00:35:26.476130 | controller | ok 2025-12-06 00:35:26.492215 | 2025-12-06 00:35:26.492294 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-06 00:35:26.792815 | controller -> localhost | ok 2025-12-06 00:35:26.807803 | 2025-12-06 00:35:26.807944 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-06 00:35:26.839239 | controller | ok 2025-12-06 00:35:26.862687 | controller | included: /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-06 00:35:26.871814 | 2025-12-06 00:35:26.871906 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-06 00:35:27.173245 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-06 00:35:27.173540 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/work/243494fa224d4771acd1bcedf31c7d4b_id_ecdsa. 2025-12-06 00:35:27.173616 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/work/243494fa224d4771acd1bcedf31c7d4b_id_ecdsa.pub. 2025-12-06 00:35:27.173680 | controller -> localhost | The key fingerprint is: 2025-12-06 00:35:27.173726 | controller -> localhost | SHA256:/kHjaoIunDhH8pfl2f0RRhM4jaRHaaWkZBVt3UQc2co zuul-build-sshkey 2025-12-06 00:35:27.173922 | controller -> localhost | The key's randomart image is: 2025-12-06 00:35:27.173992 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-06 00:35:27.174093 | controller -> localhost | | oo*Oo. **| 2025-12-06 00:35:27.174157 | controller -> localhost | | o =*.+...+| 2025-12-06 00:35:27.174207 | controller -> localhost | | o.ooo. . | 2025-12-06 00:35:27.174253 | controller -> localhost | | . . .E | 2025-12-06 00:35:27.174297 | controller -> localhost | | S o o | 2025-12-06 00:35:27.174341 | controller -> localhost | |. . .. o o . | 2025-12-06 00:35:27.174399 | controller -> localhost | | * . = o..o . | 2025-12-06 00:35:27.174444 | controller -> localhost | |o * + + oo.. . | 2025-12-06 00:35:27.174519 | controller -> localhost | | o +. o. ... | 2025-12-06 00:35:27.174560 | controller -> localhost | +----[SHA256]-----+ 2025-12-06 00:35:27.174655 | controller -> localhost | ok: Runtime: 0:00:00.015882 2025-12-06 00:35:27.190338 | 2025-12-06 00:35:27.190515 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-06 00:35:27.220673 | controller | ok 2025-12-06 00:35:27.234447 | controller | included: /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-06 00:35:27.249289 | 2025-12-06 00:35:27.249429 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-06 00:35:27.284691 | controller | skipping: Conditional result was False 2025-12-06 00:35:27.297122 | 2025-12-06 00:35:27.297269 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-06 00:35:28.211686 | controller | changed 2025-12-06 00:35:28.226160 | 2025-12-06 00:35:28.226426 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-06 00:35:28.888550 | controller | ok 2025-12-06 00:35:28.951738 | 2025-12-06 00:35:28.951959 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-06 00:35:32.062221 | controller | changed 2025-12-06 00:35:32.075497 | 2025-12-06 00:35:32.075658 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-06 00:35:35.162907 | controller | changed 2025-12-06 00:35:35.176455 | 2025-12-06 00:35:35.176618 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-06 00:35:35.204438 | controller | skipping: Conditional result was False 2025-12-06 00:35:35.221537 | 2025-12-06 00:35:35.221728 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-06 00:35:35.473148 | controller -> localhost | changed 2025-12-06 00:35:35.499566 | 2025-12-06 00:35:35.499784 | TASK [add-build-sshkey : Add back temp key] 2025-12-06 00:35:35.786339 | controller -> localhost | Identity added: /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/work/243494fa224d4771acd1bcedf31c7d4b_id_ecdsa (zuul-build-sshkey) 2025-12-06 00:35:35.786632 | controller -> localhost | ok: Runtime: 0:00:00.007337 2025-12-06 00:35:35.796067 | 2025-12-06 00:35:35.796164 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-06 00:35:36.497247 | controller | ok 2025-12-06 00:35:36.510835 | 2025-12-06 00:35:36.511085 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-06 00:35:36.538345 | controller | skipping: Conditional result was False 2025-12-06 00:35:36.564648 | 2025-12-06 00:35:36.564836 | TASK [include_role : remove-zuul-sshkey] 2025-12-06 00:35:36.581389 | controller | skipping: Conditional result was False 2025-12-06 00:35:36.593211 | 2025-12-06 00:35:36.593528 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-06 00:35:37.254681 | controller | ok: "logs" 2025-12-06 00:35:37.255100 | controller | ok: All items complete 2025-12-06 00:35:37.255172 | 2025-12-06 00:35:37.865809 | controller | ok: "artifacts" 2025-12-06 00:35:38.481800 | controller | ok: "docs" 2025-12-06 00:35:38.504181 | 2025-12-06 00:35:38.504389 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-06 00:35:39.195923 | controller | changed: "logs" 2025-12-06 00:35:39.807233 | controller | changed: "artifacts" 2025-12-06 00:35:40.430447 | controller | changed: "docs" 2025-12-06 00:35:40.494331 | 2025-12-06 00:35:40.494460 | PLAY RECAP 2025-12-06 00:35:40.494516 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-06 00:35:40.494552 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-06 00:35:40.494578 | 2025-12-06 00:35:40.622615 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-06 00:35:40.623479 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-06 00:35:41.178981 | 2025-12-06 00:35:41.179105 | PLAY [all] 2025-12-06 00:35:41.200906 | 2025-12-06 00:35:41.201050 | TASK [Install binary dependencies] 2025-12-06 00:35:41.281119 | controller | ok 2025-12-06 00:35:41.305406 | 2025-12-06 00:35:41.305526 | TASK [bindep : Include find tasks] 2025-12-06 00:35:41.345410 | controller | ok 2025-12-06 00:35:41.353286 | controller | included: /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-06 00:35:41.360424 | 2025-12-06 00:35:41.360493 | TASK [bindep : Look for bindep.txt] 2025-12-06 00:35:42.335737 | controller | ok 2025-12-06 00:35:42.349972 | 2025-12-06 00:35:42.350172 | TASK [bindep : Define bindep_file fact] 2025-12-06 00:35:42.377766 | controller | skipping: Conditional result was False 2025-12-06 00:35:42.392698 | 2025-12-06 00:35:42.392875 | TASK [bindep : Look for other-requirements.txt] 2025-12-06 00:35:43.055185 | controller | ok 2025-12-06 00:35:43.064251 | 2025-12-06 00:35:43.064349 | TASK [bindep : Define bindep_file fact] 2025-12-06 00:35:43.099063 | controller | skipping: Conditional result was False 2025-12-06 00:35:43.113956 | 2025-12-06 00:35:43.114173 | TASK [bindep : Look for bindep fallback file] 2025-12-06 00:35:43.141297 | controller | skipping: Conditional result was False 2025-12-06 00:35:43.157492 | 2025-12-06 00:35:43.157667 | TASK [bindep : Define bindep_file fact] 2025-12-06 00:35:43.185793 | controller | skipping: Conditional result was False 2025-12-06 00:35:43.200654 | 2025-12-06 00:35:43.200807 | TASK [bindep : Include bindep tasks] 2025-12-06 00:35:43.227559 | controller | skipping: Conditional result was False 2025-12-06 00:35:43.243235 | 2025-12-06 00:35:43.243404 | TASK [bindep : Include install tasks] 2025-12-06 00:35:43.271336 | controller | skipping: Conditional result was False 2025-12-06 00:35:43.281648 | 2025-12-06 00:35:43.281751 | LOOP [bindep : Include package tasks] 2025-12-06 00:35:43.338255 | 2025-12-06 00:35:43.338428 | TASK [Run test-setup role] 2025-12-06 00:35:43.356843 | controller | ok 2025-12-06 00:35:43.374220 | 2025-12-06 00:35:43.374358 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-06 00:35:44.033315 | controller | ok 2025-12-06 00:35:44.046932 | 2025-12-06 00:35:44.047115 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-06 00:35:44.427808 | controller | skipping: Conditional result was False 2025-12-06 00:35:44.464146 | 2025-12-06 00:35:44.464250 | PLAY RECAP 2025-12-06 00:35:44.464303 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-06 00:35:44.464333 | 2025-12-06 00:35:44.566534 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-06 00:35:44.568690 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-06 00:35:45.144336 | 2025-12-06 00:35:45.144484 | PLAY [controller] 2025-12-06 00:35:45.165665 | 2025-12-06 00:35:45.165781 | TASK [Create the /root directory] 2025-12-06 00:35:46.232582 | controller | ok 2025-12-06 00:35:46.238294 | 2025-12-06 00:35:46.238388 | TASK [Install glibc-langpack-en] 2025-12-06 00:35:54.661208 | controller | ok: Nothing to do 2025-12-06 00:35:54.673882 | 2025-12-06 00:35:54.674083 | TASK [Ensure controller directory exists] 2025-12-06 00:35:55.529622 | controller | changed 2025-12-06 00:35:55.541749 | 2025-12-06 00:35:55.541889 | TASK [Install container runtime] 2025-12-06 00:35:55.622409 | controller | ok 2025-12-06 00:35:55.680909 | 2025-12-06 00:35:55.681081 | LOOP [ensure-podman : Find distribution installation] 2025-12-06 00:35:55.708452 | controller | ok: "/var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-06 00:35:55.723914 | controller | included: /var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-06 00:35:55.731132 | 2025-12-06 00:35:55.731204 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-06 00:38:01.844922 | controller | changed 2025-12-06 00:38:01.858543 | 2025-12-06 00:38:01.858721 | TASK [ensure-podman : Fetch podman version] 2025-12-06 00:38:03.047216 | controller | Client: Podman Engine 2025-12-06 00:38:03.047349 | controller | Version: 4.6.2 2025-12-06 00:38:03.047411 | controller | API Version: 4.6.2 2025-12-06 00:38:03.047464 | controller | Go Version: go1.19.12 2025-12-06 00:38:03.047538 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-06 00:38:03.047628 | controller | OS/Arch: linux/amd64 2025-12-06 00:38:03.236090 | controller | ok: Runtime: 0:00:00.317224 2025-12-06 00:38:03.243191 | 2025-12-06 00:38:03.243270 | TASK [ensure-podman : Print podman version installed] 2025-12-06 00:38:03.276256 | Podman version: Client: Podman Engine 2025-12-06 00:38:03.276454 | Version: 4.6.2 2025-12-06 00:38:03.276492 | API Version: 4.6.2 2025-12-06 00:38:03.276519 | Go Version: go1.19.12 2025-12-06 00:38:03.276543 | Built: Mon Aug 28 19:38:31 2023 2025-12-06 00:38:03.276567 | OS/Arch: linux/amd64 2025-12-06 00:38:03.283714 | 2025-12-06 00:38:03.283835 | TASK [ensure-podman : Validate podman engine] 2025-12-06 00:38:03.644456 | controller | skipping: Conditional result was False 2025-12-06 00:38:03.650859 | 2025-12-06 00:38:03.650929 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-06 00:38:03.664584 | controller | skipping: Conditional result was False 2025-12-06 00:38:03.675753 | 2025-12-06 00:38:03.675825 | TASK [Ensure python3.8 is present] 2025-12-06 00:38:03.689079 | controller | skipping: Conditional result was False 2025-12-06 00:38:03.695048 | 2025-12-06 00:38:03.695118 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-06 00:38:03.713376 | controller | ok 2025-12-06 00:38:03.732712 | 2025-12-06 00:38:03.732807 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-06 00:38:07.595494 | controller | ok: Nothing to do 2025-12-06 00:38:07.606645 | 2025-12-06 00:38:07.606792 | TASK [our-ensure-python : Also install python3-devel] 2025-12-06 00:38:22.778451 | controller | changed 2025-12-06 00:38:22.794825 | 2025-12-06 00:38:22.794955 | TASK [Run ensure-virtualenv role] 2025-12-06 00:38:22.819401 | controller | ok 2025-12-06 00:38:22.849820 | 2025-12-06 00:38:22.849954 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-06 00:38:23.630865 | controller | /usr/bin/virtualenv 2025-12-06 00:38:24.233627 | controller | ok: Runtime: 0:00:00.006131 2025-12-06 00:38:24.248370 | 2025-12-06 00:38:24.248560 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-06 00:38:24.274223 | controller | skipping: Conditional result was False 2025-12-06 00:38:24.274518 | controller | ok: All items complete 2025-12-06 00:38:24.274556 | 2025-12-06 00:38:24.292993 | 2025-12-06 00:38:24.293243 | TASK [Find the full path of the Python interpreter] 2025-12-06 00:38:25.084660 | controller | /usr/bin/python3 2025-12-06 00:38:25.659263 | controller | ok 2025-12-06 00:38:25.674679 | 2025-12-06 00:38:25.674886 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-06 00:38:27.639693 | controller | created virtual environment CPython3.11.0.final.0-64 in 879ms 2025-12-06 00:38:27.746050 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-06 00:38:27.746916 | 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-12-06 00:38:27.747534 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-06 00:38:27.747694 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-06 00:38:28.061659 | controller | changed 2025-12-06 00:38:28.074514 | 2025-12-06 00:38:28.074662 | TASK [Set selinux package] 2025-12-06 00:38:28.105211 | controller | ok 2025-12-06 00:38:28.120770 | 2025-12-06 00:38:28.121055 | TASK [Set selinux package (Fedora)] 2025-12-06 00:38:28.184454 | controller | ok 2025-12-06 00:38:28.195890 | 2025-12-06 00:38:28.196070 | TASK [Install selinux into virtualenv] 2025-12-06 00:38:31.537649 | controller | Collecting selinux-please-lie-to-me 2025-12-06 00:38:31.609094 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-06 00:38:32.148318 | controller | Collecting setuptools<50.0.0 2025-12-06 00:38:32.156080 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-06 00:38:32.212341 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 17.1 MB/s eta 0:00:00 2025-12-06 00:38:32.365511 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-06 00:38:32.365876 | controller | Attempting uninstall: setuptools 2025-12-06 00:38:32.370636 | controller | Found existing installation: setuptools 62.6.0 2025-12-06 00:38:32.475733 | controller | Uninstalling setuptools-62.6.0: 2025-12-06 00:38:32.494989 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-06 00:38:33.391787 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-06 00:38:33.583038 | controller | 2025-12-06 00:38:34.021319 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-06 00:38:34.021384 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-06 00:38:34.601621 | controller | ok: Runtime: 0:00:04.896326 2025-12-06 00:38:34.614050 | 2025-12-06 00:38:34.614184 | TASK [Install pytest-forked into virtualenv] 2025-12-06 00:38:36.225683 | controller | Collecting pytest-forked 2025-12-06 00:38:36.316742 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-06 00:38:36.392206 | controller | Collecting py 2025-12-06 00:38:36.398522 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-06 00:38:36.449369 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 1.9 MB/s eta 0:00:00 2025-12-06 00:38:36.653076 | controller | Collecting pytest>=3.10 2025-12-06 00:38:36.657665 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-12-06 00:38:36.688438 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 13.6 MB/s eta 0:00:00 2025-12-06 00:38:36.755513 | controller | Collecting iniconfig>=1.0.1 2025-12-06 00:38:36.762996 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-06 00:38:36.849912 | controller | Collecting packaging>=22 2025-12-06 00:38:36.858323 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-06 00:38:36.881275 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 3.7 MB/s eta 0:00:00 2025-12-06 00:38:36.930874 | controller | Collecting pluggy<2,>=1.5 2025-12-06 00:38:36.935292 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-06 00:38:37.022762 | controller | Collecting pygments>=2.7.2 2025-12-06 00:38:37.030083 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-06 00:38:37.078310 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 30.5 MB/s eta 0:00:00 2025-12-06 00:38:37.243754 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-06 00:38:39.703002 | 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-12-06 00:38:39.716362 | controller | 2025-12-06 00:38:40.077103 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-06 00:38:40.077171 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-06 00:38:40.503229 | controller | ok: Runtime: 0:00:04.648214 2025-12-06 00:38:40.517580 | 2025-12-06 00:38:40.517743 | TASK [Update pip] 2025-12-06 00:38:42.030165 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-06 00:38:42.332125 | controller | Collecting pip 2025-12-06 00:38:42.405657 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-06 00:38:42.501309 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 19.9 MB/s eta 0:00:00 2025-12-06 00:38:42.622622 | controller | Installing collected packages: pip 2025-12-06 00:38:42.624085 | controller | Attempting uninstall: pip 2025-12-06 00:38:42.629189 | controller | Found existing installation: pip 22.2.2 2025-12-06 00:38:42.855790 | controller | Uninstalling pip-22.2.2: 2025-12-06 00:38:42.886434 | controller | Successfully uninstalled pip-22.2.2 2025-12-06 00:38:44.861698 | controller | Successfully installed pip-25.3 2025-12-06 00:38:45.421311 | controller | ok: Runtime: 0:00:03.795934 2025-12-06 00:38:45.434609 | 2025-12-06 00:38:45.434745 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-06 00:38:46.432204 | controller | changed 2025-12-06 00:38:46.444965 | 2025-12-06 00:38:46.445220 | TASK [Install ansible into virtualenv] 2025-12-06 00:38:47.671823 | controller | Processing ./src/github.com/ansible/ansible 2025-12-06 00:38:47.677384 | controller | Installing build dependencies: started 2025-12-06 00:38:49.627221 | controller | Installing build dependencies: finished with status 'done' 2025-12-06 00:38:51.382673 | controller | Getting requirements to build wheel: started 2025-12-06 00:38:51.382759 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-06 00:38:51.383186 | controller | Preparing metadata (pyproject.toml): started 2025-12-06 00:38:52.320286 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-06 00:38:52.324927 | 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-12-06 00:38:52.329915 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-06 00:38:52.829151 | controller | ERROR 2025-12-06 00:38:52.829414 | controller | { 2025-12-06 00:38:52.829477 | controller | "delta": "0:00:05.479268", 2025-12-06 00:38:52.829521 | controller | "end": "2025-12-06 00:38:52.595976", 2025-12-06 00:38:52.829560 | controller | "msg": "non-zero return code", 2025-12-06 00:38:52.829614 | controller | "rc": 1, 2025-12-06 00:38:52.829653 | controller | "start": "2025-12-06 00:38:47.116708" 2025-12-06 00:38:52.829688 | controller | } failure 2025-12-06 00:38:52.832176 | 2025-12-06 00:38:52.832307 | PLAY RECAP 2025-12-06 00:38:52.832396 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-06 00:38:52.832441 | 2025-12-06 00:38:52.958938 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-06 00:38:52.959987 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-06 00:38:53.556862 | 2025-12-06 00:38:53.556968 | PLAY [all] 2025-12-06 00:38:53.579349 | 2025-12-06 00:38:53.579437 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-06 00:38:55.428465 | controller | changed: non-zero return code 2025-12-06 00:38:55.436851 | 2025-12-06 00:38:55.436974 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-06 00:38:55.462569 | controller | skipping: Conditional result was False 2025-12-06 00:38:55.479539 | 2025-12-06 00:38:55.479692 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-06 00:38:55.508554 | 2025-12-06 00:38:55.508722 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-06 00:38:55.528975 | 2025-12-06 00:38:55.529169 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-06 00:38:55.542931 | controller | skipping: Conditional result was False 2025-12-06 00:38:55.549283 | 2025-12-06 00:38:55.549388 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-06 00:38:55.569093 | 2025-12-06 00:38:55.569250 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-06 00:38:55.582575 | controller | skipping: Conditional result was False 2025-12-06 00:38:55.588603 | 2025-12-06 00:38:55.588695 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-06 00:38:55.602834 | controller | skipping: Conditional result was False 2025-12-06 00:38:55.608802 | 2025-12-06 00:38:55.608874 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-06 00:38:55.621919 | controller | skipping: Conditional result was False 2025-12-06 00:38:55.647633 | 2025-12-06 00:38:55.647712 | PLAY RECAP 2025-12-06 00:38:55.647753 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-06 00:38:55.647773 | 2025-12-06 00:38:55.745390 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-06 00:38:55.747106 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-06 00:38:56.354905 | 2025-12-06 00:38:56.355051 | PLAY [all:!appliance*] 2025-12-06 00:38:56.378688 | 2025-12-06 00:38:56.378814 | TASK [unregister the node] 2025-12-06 00:38:56.730805 | controller | skipping: Conditional result was False 2025-12-06 00:38:56.737209 | 2025-12-06 00:38:56.737304 | TASK [include_role : fetch-output] 2025-12-06 00:38:56.769882 | controller | ok 2025-12-06 00:38:56.801171 | 2025-12-06 00:38:56.801336 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-06 00:38:56.867988 | controller | skipping: Conditional result was False 2025-12-06 00:38:56.878202 | 2025-12-06 00:38:56.878305 | TASK [fetch-output : Set log path for single node] 2025-12-06 00:38:56.910920 | controller | ok 2025-12-06 00:38:56.919407 | 2025-12-06 00:38:56.919519 | LOOP [fetch-output : Ensure local output dirs] 2025-12-06 00:38:57.307091 | controller -> localhost | ok: "/var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/work/logs" 2025-12-06 00:38:57.547786 | controller -> localhost | changed: "/var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/work/artifacts" 2025-12-06 00:38:57.800767 | controller -> localhost | changed: "/var/lib/zuul/builds/243494fa224d4771acd1bcedf31c7d4b/work/docs" 2025-12-06 00:38:57.824145 | 2025-12-06 00:38:57.824515 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-06 00:39:00.081930 | controller | changed: 2025-12-06 00:39:00.082174 | controller | .d..t...... ./ 2025-12-06 00:39:00.082220 | controller | cd+++++++++ controller/ 2025-12-06 00:39:00.082272 | controller | changed: All items complete 2025-12-06 00:39:00.082301 | 2025-12-06 00:39:02.114349 | controller | changed: .d..t...... ./ 2025-12-06 00:39:04.127695 | controller | changed: .d..t...... ./ 2025-12-06 00:39:04.157919 | 2025-12-06 00:39:04.158148 | TASK [include_role : fetch-output-openshift] 2025-12-06 00:39:04.185621 | controller | skipping: Conditional result was False 2025-12-06 00:39:04.200145 | 2025-12-06 00:39:04.200294 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-06 00:39:04.234508 | controller | skipping: Conditional result was False 2025-12-06 00:39:04.253366 | controller | skipping: Conditional result was False 2025-12-06 00:39:04.298282 | 2025-12-06 00:39:04.298393 | PLAY [localhost] 2025-12-06 00:39:04.316290 | 2025-12-06 00:39:04.316398 | TASK [Run Zuul manifest role] 2025-12-06 00:39:04.336940 | localhost | ok 2025-12-06 00:39:04.357383 | 2025-12-06 00:39:04.357537 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-06 00:39:04.721064 | localhost | changed 2025-12-06 00:39:04.725703 | 2025-12-06 00:39:04.725769 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-06 00:39:04.764389 | localhost | ok 2025-12-06 00:39:04.772360 | 2025-12-06 00:39:04.772421 | TASK [Set zuul-log-path fact] 2025-12-06 00:39:04.790630 | localhost | ok 2025-12-06 00:39:04.826441 | 2025-12-06 00:39:04.826546 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-06 00:39:04.864062 | localhost | ok 2025-12-06 00:39:04.871896 | 2025-12-06 00:39:04.871956 | LOOP [Run upload-logs-swift role] 2025-12-06 00:39:04.917304 | localhost | Output suppressed because no_log was given 2025-12-06 00:39:04.950229 | 2025-12-06 00:39:04.950344 | TASK [Set zuul-log-path fact] 2025-12-06 00:39:04.985346 | localhost | skipping: Conditional result was False 2025-12-06 00:39:04.998476 | 2025-12-06 00:39:04.998613 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-06 00:39:05.471794 | localhost -> localhost | ok: Runtime: 0:00:00.008754 2025-12-06 00:39:05.477190 | 2025-12-06 00:39:05.477265 | TASK [upload-logs-swift : Upload logs to swift]