2025-10-14 00:12:10.822530 | Job console starting... 2025-10-14 00:12:10.832701 | Updating repositories 2025-10-14 00:12:10.970513 | Preparing job workspace 2025-10-14 00:12:15.455489 | Running Ansible setup... 2025-10-14 00:12:20.309958 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-14 00:12:21.170330 | 2025-10-14 00:12:21.170501 | PLAY [localhost] 2025-10-14 00:12:21.182209 | 2025-10-14 00:12:21.182368 | TASK [Gathering Facts] 2025-10-14 00:12:22.634662 | localhost | ok 2025-10-14 00:12:22.669786 | 2025-10-14 00:12:22.671123 | TASK [Setup log path fact] 2025-10-14 00:12:22.703542 | localhost | ok 2025-10-14 00:12:22.719091 | 2025-10-14 00:12:22.719214 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-14 00:12:22.750057 | localhost | ok 2025-10-14 00:12:22.765783 | 2025-10-14 00:12:22.765924 | TASK [emit-job-header : Print job information] 2025-10-14 00:12:22.826508 | # Job Information 2025-10-14 00:12:22.826700 | Ansible Version: 2.15.12 2025-10-14 00:12:22.826787 | Job: ansible-test-sanity-docker-milestone 2025-10-14 00:12:22.826829 | Pipeline: periodic 2025-10-14 00:12:22.826859 | Executor: ze03.softwarefactory-project.io 2025-10-14 00:12:22.826887 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-14 00:12:22.826919 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/905/ansible/905e1c4b3f91496aa433a972cb8a534b/ 2025-10-14 00:12:22.826948 | Event ID: 082694bef8494c6a9293b529962a7d9e 2025-10-14 00:12:22.833214 | 2025-10-14 00:12:22.833366 | LOOP [emit-job-header : Print node information] 2025-10-14 00:12:23.111473 | localhost | ok: 2025-10-14 00:12:23.111682 | localhost | # Node Information 2025-10-14 00:12:23.111717 | localhost | Inventory Hostname: controller 2025-10-14 00:12:23.111776 | localhost | Hostname: np0005486544 2025-10-14 00:12:23.111808 | localhost | Username: zuul 2025-10-14 00:12:23.111842 | localhost | Distro: Fedora 37 2025-10-14 00:12:23.111869 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-10-14 00:12:23.111894 | localhost | Region: ca-ymq-1 2025-10-14 00:12:23.111916 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-14 00:12:23.111939 | localhost | Product Name: OpenStack Nova 2025-10-14 00:12:23.111960 | localhost | Interface IP: 162.253.55.186 2025-10-14 00:12:23.122967 | 2025-10-14 00:12:23.123090 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-14 00:12:23.728867 | localhost -> localhost | changed 2025-10-14 00:12:23.735249 | 2025-10-14 00:12:23.735385 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-14 00:12:25.130498 | localhost -> localhost | changed 2025-10-14 00:12:25.153661 | 2025-10-14 00:12:25.153878 | PLAY [all:!appliance*] 2025-10-14 00:12:25.195120 | 2025-10-14 00:12:25.195264 | TASK [include_role : start-zuul-console] 2025-10-14 00:12:25.216946 | controller | ok 2025-10-14 00:12:25.233209 | 2025-10-14 00:12:25.233356 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-14 00:12:25.756482 | controller | ok 2025-10-14 00:12:25.848244 | 2025-10-14 00:12:25.848405 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-14 00:12:48.537123 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-14 00:12:48.549044 | 2025-10-14 00:12:48.549315 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-14 00:12:49.118536 | controller | skipping: Conditional result was False 2025-10-14 00:12:49.127566 | 2025-10-14 00:12:49.127701 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-14 00:12:49.163371 | controller | skipping: Conditional result was False 2025-10-14 00:12:49.179134 | 2025-10-14 00:12:49.179301 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-14 00:12:49.201420 | controller | skipping: Conditional result was False 2025-10-14 00:12:49.212512 | 2025-10-14 00:12:49.212653 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-14 00:12:49.237515 | controller | skipping: Conditional result was False 2025-10-14 00:12:49.246435 | 2025-10-14 00:12:49.246586 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-14 00:12:49.270833 | controller | skipping: Conditional result was False 2025-10-14 00:12:49.279476 | 2025-10-14 00:12:49.279763 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-14 00:12:49.323466 | controller | skipping: Conditional result was False 2025-10-14 00:12:49.337750 | 2025-10-14 00:12:49.337865 | TASK [Disable Fedora Modular] 2025-10-14 00:12:49.646301 | controller | changed 2025-10-14 00:12:49.655865 | 2025-10-14 00:12:49.656024 | TASK [Enable EPEL] 2025-10-14 00:12:49.682176 | controller | skipping: Conditional result was False 2025-10-14 00:12:49.691263 | 2025-10-14 00:12:49.691385 | TASK [Register the RHEL node] 2025-10-14 00:12:50.257060 | 2025-10-14 00:12:50.257236 | TASK [Show the subscription-manager status] 2025-10-14 00:12:50.830120 | controller | skipping: Conditional result was False 2025-10-14 00:12:50.837132 | 2025-10-14 00:12:50.837230 | TASK [Enable EPEL on RHEL] 2025-10-14 00:12:51.391707 | controller | skipping: Conditional result was False 2025-10-14 00:12:51.399198 | 2025-10-14 00:12:51.399340 | TASK [Install git and tox] 2025-10-14 00:13:43.225396 | controller | changed 2025-10-14 00:13:43.236051 | 2025-10-14 00:13:43.236244 | TASK [include_role : prepare-workspace] 2025-10-14 00:13:43.261499 | controller | ok 2025-10-14 00:13:43.343529 | 2025-10-14 00:13:43.343706 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-14 00:13:43.605440 | controller | ok 2025-10-14 00:13:43.614270 | 2025-10-14 00:13:43.614408 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-14 00:13:56.549960 | controller | Output suppressed because no_log was given 2025-10-14 00:13:56.565187 | 2025-10-14 00:13:56.565303 | TASK [include_role : prepare-workspace-openshift] 2025-10-14 00:13:56.599744 | controller | skipping: Conditional result was False 2025-10-14 00:13:56.636436 | 2025-10-14 00:13:56.636540 | PLAY [all:!appliance] 2025-10-14 00:13:56.657277 | 2025-10-14 00:13:56.657408 | TASK [Run add-build-sshkey role (RSA)] 2025-10-14 00:13:56.688032 | controller | ok 2025-10-14 00:13:56.711291 | 2025-10-14 00:13:56.711418 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-14 00:13:56.955142 | controller -> localhost | ok 2025-10-14 00:13:56.964341 | 2025-10-14 00:13:56.964483 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-14 00:13:56.985339 | controller | ok 2025-10-14 00:13:57.000949 | controller | included: /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-14 00:13:57.008766 | 2025-10-14 00:13:57.008912 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-14 00:13:57.588561 | controller -> localhost | Generating public/private rsa key pair. 2025-10-14 00:13:57.588820 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/work/905e1c4b3f91496aa433a972cb8a534b_id_rsa. 2025-10-14 00:13:57.588863 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/work/905e1c4b3f91496aa433a972cb8a534b_id_rsa.pub. 2025-10-14 00:13:57.588894 | controller -> localhost | The key fingerprint is: 2025-10-14 00:13:57.588921 | controller -> localhost | SHA256:jUHYzkwvOY4XOGnVenJBPkLAO4hnhuv5tk2oBksHIz4 zuul-build-sshkey 2025-10-14 00:13:57.588949 | controller -> localhost | The key's randomart image is: 2025-10-14 00:13:57.588974 | controller -> localhost | +---[RSA 2048]----+ 2025-10-14 00:13:57.589001 | controller -> localhost | | ..+oo. | 2025-10-14 00:13:57.589029 | controller -> localhost | | oo+.o | 2025-10-14 00:13:57.589054 | controller -> localhost | | o . Xo+o. | 2025-10-14 00:13:57.589077 | controller -> localhost | |.oo = B @=+. | 2025-10-14 00:13:57.589099 | controller -> localhost | |o o= . =SB. | 2025-10-14 00:13:57.589132 | controller -> localhost | |.E.. .. o | 2025-10-14 00:13:57.589161 | controller -> localhost | |.+o.. .. | 2025-10-14 00:13:57.589188 | controller -> localhost | |. +..o | 2025-10-14 00:13:57.589212 | controller -> localhost | | ..oo.. | 2025-10-14 00:13:57.589240 | controller -> localhost | +----[SHA256]-----+ 2025-10-14 00:13:57.589299 | controller -> localhost | ok: Runtime: 0:00:00.060449 2025-10-14 00:13:57.600328 | 2025-10-14 00:13:57.600472 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-14 00:13:57.634668 | controller | ok 2025-10-14 00:13:57.646403 | controller | included: /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-14 00:13:57.656853 | 2025-10-14 00:13:57.656985 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-14 00:13:57.681415 | controller | skipping: Conditional result was False 2025-10-14 00:13:57.691207 | 2025-10-14 00:13:57.691391 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-14 00:13:58.152914 | controller | changed 2025-10-14 00:13:58.172835 | 2025-10-14 00:13:58.173011 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-14 00:13:58.398605 | controller | ok 2025-10-14 00:13:58.406294 | 2025-10-14 00:13:58.406411 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-14 00:13:59.095364 | controller | changed 2025-10-14 00:13:59.102390 | 2025-10-14 00:13:59.102464 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-14 00:13:59.703389 | controller | changed 2025-10-14 00:13:59.710760 | 2025-10-14 00:13:59.710930 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-14 00:13:59.735951 | controller | skipping: Conditional result was False 2025-10-14 00:13:59.745953 | 2025-10-14 00:13:59.746108 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-14 00:14:00.140177 | controller -> localhost | changed 2025-10-14 00:14:00.151979 | 2025-10-14 00:14:00.152092 | TASK [add-build-sshkey : Add back temp key] 2025-10-14 00:14:00.462673 | controller -> localhost | Identity added: /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/work/905e1c4b3f91496aa433a972cb8a534b_id_rsa (zuul-build-sshkey) 2025-10-14 00:14:00.462974 | controller -> localhost | ok: Runtime: 0:00:00.011266 2025-10-14 00:14:00.471301 | 2025-10-14 00:14:00.471452 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-14 00:14:00.788454 | controller | ok 2025-10-14 00:14:00.797504 | 2025-10-14 00:14:00.797637 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-14 00:14:00.833792 | controller | skipping: Conditional result was False 2025-10-14 00:14:00.847864 | 2025-10-14 00:14:00.847992 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-14 00:14:00.878987 | controller | ok 2025-10-14 00:14:00.900955 | 2025-10-14 00:14:00.901089 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-14 00:14:01.182211 | controller -> localhost | ok 2025-10-14 00:14:01.192213 | 2025-10-14 00:14:01.192333 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-14 00:14:01.223743 | controller | ok 2025-10-14 00:14:01.238374 | controller | included: /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-14 00:14:01.246160 | 2025-10-14 00:14:01.246320 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-14 00:14:01.567284 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-14 00:14:01.567545 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/work/905e1c4b3f91496aa433a972cb8a534b_id_ecdsa. 2025-10-14 00:14:01.567575 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/work/905e1c4b3f91496aa433a972cb8a534b_id_ecdsa.pub. 2025-10-14 00:14:01.567606 | controller -> localhost | The key fingerprint is: 2025-10-14 00:14:01.567626 | controller -> localhost | SHA256:cYAP+0IXySikb6Ov4UyuHUQIKLKoJ5CKrak8RdiPmZ0 zuul-build-sshkey 2025-10-14 00:14:01.567647 | controller -> localhost | The key's randomart image is: 2025-10-14 00:14:01.567665 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-14 00:14:01.567683 | controller -> localhost | |o .. +.. | 2025-10-14 00:14:01.567700 | controller -> localhost | |=. .. + +. | 2025-10-14 00:14:01.567716 | controller -> localhost | |=o= . +... | 2025-10-14 00:14:01.567756 | controller -> localhost | |=o + o oo | 2025-10-14 00:14:01.567775 | controller -> localhost | |=.o X..oS | 2025-10-14 00:14:01.567792 | controller -> localhost | |=.oB E. . | 2025-10-14 00:14:01.567808 | controller -> localhost | | =* . | 2025-10-14 00:14:01.567825 | controller -> localhost | |+B + | 2025-10-14 00:14:01.567841 | controller -> localhost | |+oB.. | 2025-10-14 00:14:01.567857 | controller -> localhost | +----[SHA256]-----+ 2025-10-14 00:14:01.567917 | controller -> localhost | ok: Runtime: 0:00:00.012640 2025-10-14 00:14:01.575267 | 2025-10-14 00:14:01.575389 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-14 00:14:01.606411 | controller | ok 2025-10-14 00:14:01.620359 | controller | included: /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-14 00:14:01.637627 | 2025-10-14 00:14:01.637834 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-14 00:14:01.664006 | controller | skipping: Conditional result was False 2025-10-14 00:14:01.677394 | 2025-10-14 00:14:01.677552 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-14 00:14:01.967627 | controller | changed 2025-10-14 00:14:01.977130 | 2025-10-14 00:14:01.977262 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-14 00:14:02.203307 | controller | ok 2025-10-14 00:14:02.209512 | 2025-10-14 00:14:02.209590 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-14 00:14:02.840910 | controller | changed 2025-10-14 00:14:02.847791 | 2025-10-14 00:14:02.847881 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-14 00:14:03.485857 | controller | changed 2025-10-14 00:14:03.495630 | 2025-10-14 00:14:03.495800 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-14 00:14:03.531790 | controller | skipping: Conditional result was False 2025-10-14 00:14:03.540439 | 2025-10-14 00:14:03.540566 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-14 00:14:03.805258 | controller -> localhost | changed 2025-10-14 00:14:03.823573 | 2025-10-14 00:14:03.823788 | TASK [add-build-sshkey : Add back temp key] 2025-10-14 00:14:04.121931 | controller -> localhost | Identity added: /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/work/905e1c4b3f91496aa433a972cb8a534b_id_ecdsa (zuul-build-sshkey) 2025-10-14 00:14:04.122225 | controller -> localhost | ok: Runtime: 0:00:00.009841 2025-10-14 00:14:04.129996 | 2025-10-14 00:14:04.130141 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-14 00:14:04.331336 | controller | ok 2025-10-14 00:14:04.337490 | 2025-10-14 00:14:04.337621 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-14 00:14:04.364085 | controller | skipping: Conditional result was False 2025-10-14 00:14:04.389940 | 2025-10-14 00:14:04.390075 | TASK [include_role : remove-zuul-sshkey] 2025-10-14 00:14:04.404621 | controller | skipping: Conditional result was False 2025-10-14 00:14:04.412875 | 2025-10-14 00:14:04.412974 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-14 00:14:04.643024 | controller | ok: "logs" 2025-10-14 00:14:04.643534 | controller | ok: All items complete 2025-10-14 00:14:04.643629 | 2025-10-14 00:14:04.827697 | controller | ok: "artifacts" 2025-10-14 00:14:05.028281 | controller | ok: "docs" 2025-10-14 00:14:05.043444 | 2025-10-14 00:14:05.043556 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-14 00:14:05.267990 | controller | changed: "logs" 2025-10-14 00:14:05.465373 | controller | changed: "artifacts" 2025-10-14 00:14:05.673107 | controller | changed: "docs" 2025-10-14 00:14:05.706058 | 2025-10-14 00:14:05.706184 | PLAY RECAP 2025-10-14 00:14:05.706241 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-14 00:14:05.706272 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-14 00:14:05.706291 | 2025-10-14 00:14:05.857556 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-14 00:14:05.858403 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-14 00:14:06.492343 | 2025-10-14 00:14:06.492492 | PLAY [all] 2025-10-14 00:14:06.518364 | 2025-10-14 00:14:06.518523 | TASK [Install binary dependencies] 2025-10-14 00:14:06.581924 | controller | ok 2025-10-14 00:14:06.610022 | 2025-10-14 00:14:06.610212 | TASK [bindep : Include find tasks] 2025-10-14 00:14:06.652924 | controller | ok 2025-10-14 00:14:06.664773 | controller | included: /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-14 00:14:06.673050 | 2025-10-14 00:14:06.673186 | TASK [bindep : Look for bindep.txt] 2025-10-14 00:14:07.042493 | controller | ok 2025-10-14 00:14:07.048308 | 2025-10-14 00:14:07.048379 | TASK [bindep : Define bindep_file fact] 2025-10-14 00:14:07.062276 | controller | skipping: Conditional result was False 2025-10-14 00:14:07.068911 | 2025-10-14 00:14:07.069012 | TASK [bindep : Look for other-requirements.txt] 2025-10-14 00:14:07.261068 | controller | ok 2025-10-14 00:14:07.267027 | 2025-10-14 00:14:07.267134 | TASK [bindep : Define bindep_file fact] 2025-10-14 00:14:07.291766 | controller | skipping: Conditional result was False 2025-10-14 00:14:07.301782 | 2025-10-14 00:14:07.301914 | TASK [bindep : Look for bindep fallback file] 2025-10-14 00:14:07.327866 | controller | skipping: Conditional result was False 2025-10-14 00:14:07.335690 | 2025-10-14 00:14:07.335852 | TASK [bindep : Define bindep_file fact] 2025-10-14 00:14:07.360520 | controller | skipping: Conditional result was False 2025-10-14 00:14:07.370910 | 2025-10-14 00:14:07.371069 | TASK [bindep : Include bindep tasks] 2025-10-14 00:14:07.407666 | controller | skipping: Conditional result was False 2025-10-14 00:14:07.414130 | 2025-10-14 00:14:07.414260 | TASK [bindep : Include install tasks] 2025-10-14 00:14:07.439047 | controller | skipping: Conditional result was False 2025-10-14 00:14:07.445787 | 2025-10-14 00:14:07.445924 | LOOP [bindep : Include package tasks] 2025-10-14 00:14:07.507786 | 2025-10-14 00:14:07.508018 | TASK [Run test-setup role] 2025-10-14 00:14:07.533717 | controller | ok 2025-10-14 00:14:07.559838 | 2025-10-14 00:14:07.560026 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-14 00:14:07.795915 | controller | ok 2025-10-14 00:14:07.802156 | 2025-10-14 00:14:07.802272 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-14 00:14:08.337087 | controller | skipping: Conditional result was False 2025-10-14 00:14:08.378406 | 2025-10-14 00:14:08.378547 | PLAY RECAP 2025-10-14 00:14:08.378609 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-14 00:14:08.378645 | 2025-10-14 00:14:08.534656 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-14 00:14:08.536428 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-14 00:14:09.281341 | 2025-10-14 00:14:09.281506 | PLAY [controller] 2025-10-14 00:14:09.315053 | 2025-10-14 00:14:09.315253 | TASK [Create the /root directory] 2025-10-14 00:14:09.686297 | controller | ok 2025-10-14 00:14:09.693468 | 2025-10-14 00:14:09.693609 | TASK [Install glibc-langpack-en] 2025-10-14 00:14:13.730969 | controller | ok: Nothing to do 2025-10-14 00:14:13.742214 | 2025-10-14 00:14:13.742412 | TASK [Ensure controller directory exists] 2025-10-14 00:14:13.968034 | controller | changed 2025-10-14 00:14:13.977720 | 2025-10-14 00:14:13.977940 | TASK [Install container runtime] 2025-10-14 00:14:14.030532 | controller | ok 2025-10-14 00:14:14.076210 | 2025-10-14 00:14:14.076388 | LOOP [ensure-podman : Find distribution installation] 2025-10-14 00:14:14.100170 | controller | ok: "/var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-14 00:14:14.113218 | controller | included: /var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-14 00:14:14.122016 | 2025-10-14 00:14:14.122146 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-14 00:15:22.234029 | controller | changed 2025-10-14 00:15:22.241605 | 2025-10-14 00:15:22.241739 | TASK [ensure-podman : Fetch podman version] 2025-10-14 00:15:22.785181 | controller | Client: Podman Engine 2025-10-14 00:15:22.785289 | controller | Version: 4.6.2 2025-10-14 00:15:22.785335 | controller | API Version: 4.6.2 2025-10-14 00:15:22.785382 | controller | Go Version: go1.19.12 2025-10-14 00:15:22.785433 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-14 00:15:22.785476 | controller | OS/Arch: linux/amd64 2025-10-14 00:15:23.289246 | controller | ok: Runtime: 0:00:00.179809 2025-10-14 00:15:23.310316 | 2025-10-14 00:15:23.310452 | TASK [ensure-podman : Print podman version installed] 2025-10-14 00:15:23.346624 | Podman version: Client: Podman Engine 2025-10-14 00:15:23.346892 | Version: 4.6.2 2025-10-14 00:15:23.346934 | API Version: 4.6.2 2025-10-14 00:15:23.346971 | Go Version: go1.19.12 2025-10-14 00:15:23.347026 | Built: Mon Aug 28 19:38:31 2023 2025-10-14 00:15:23.347062 | OS/Arch: linux/amd64 2025-10-14 00:15:23.357516 | 2025-10-14 00:15:23.357634 | TASK [ensure-podman : Validate podman engine] 2025-10-14 00:15:23.903487 | controller | skipping: Conditional result was False 2025-10-14 00:15:23.915871 | 2025-10-14 00:15:23.916043 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-14 00:15:23.933203 | controller | skipping: Conditional result was False 2025-10-14 00:15:23.949519 | 2025-10-14 00:15:23.949652 | TASK [Ensure python3.8 is present] 2025-10-14 00:15:23.964084 | controller | skipping: Conditional result was False 2025-10-14 00:15:23.973244 | 2025-10-14 00:15:23.973391 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-14 00:15:23.996808 | controller | ok 2025-10-14 00:15:24.021556 | 2025-10-14 00:15:24.021744 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-14 00:15:25.521374 | controller | ok: Nothing to do 2025-10-14 00:15:25.532537 | 2025-10-14 00:15:25.532676 | TASK [our-ensure-python : Also install python3-devel] 2025-10-14 00:15:36.345874 | controller | changed 2025-10-14 00:15:36.384341 | 2025-10-14 00:15:36.384472 | TASK [Run ensure-virtualenv role] 2025-10-14 00:15:36.417843 | controller | ok 2025-10-14 00:15:36.486323 | 2025-10-14 00:15:36.486583 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-14 00:15:36.816358 | controller | /usr/bin/virtualenv 2025-10-14 00:15:37.109590 | controller | ok: Runtime: 0:00:00.005806 2025-10-14 00:15:37.119839 | 2025-10-14 00:15:37.120014 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-14 00:15:37.187050 | controller | skipping: Conditional result was False 2025-10-14 00:15:37.188894 | controller | ok: All items complete 2025-10-14 00:15:37.189014 | 2025-10-14 00:15:37.230640 | 2025-10-14 00:15:37.230829 | TASK [Find the full path of the Python interpreter] 2025-10-14 00:15:37.536247 | controller | /usr/bin/python3 2025-10-14 00:15:37.828578 | controller | ok 2025-10-14 00:15:37.854250 | 2025-10-14 00:15:37.854420 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-14 00:15:38.825581 | controller | created virtual environment CPython3.11.0.final.0-64 in 457ms 2025-10-14 00:15:38.849964 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-14 00:15:38.849982 | 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-10-14 00:15:38.849998 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-14 00:15:38.850011 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-14 00:15:38.917100 | controller | changed 2025-10-14 00:15:38.924817 | 2025-10-14 00:15:38.924932 | TASK [Set selinux package] 2025-10-14 00:15:38.982044 | controller | ok 2025-10-14 00:15:38.989346 | 2025-10-14 00:15:38.989479 | TASK [Set selinux package (Fedora)] 2025-10-14 00:15:39.064718 | controller | ok 2025-10-14 00:15:39.076879 | 2025-10-14 00:15:39.077005 | TASK [Install selinux into virtualenv] 2025-10-14 00:16:04.643177 | controller | Collecting selinux-please-lie-to-me 2025-10-14 00:16:16.995552 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-14 00:16:17.316888 | controller | Collecting setuptools<50.0.0 2025-10-14 00:16:17.322500 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-14 00:16:17.355024 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 28.3 MB/s eta 0:00:00 2025-10-14 00:16:17.434551 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-14 00:16:17.434778 | controller | Attempting uninstall: setuptools 2025-10-14 00:16:17.437156 | controller | Found existing installation: setuptools 62.6.0 2025-10-14 00:16:17.497294 | controller | Uninstalling setuptools-62.6.0: 2025-10-14 00:16:17.505381 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-14 00:16:17.865169 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-14 00:16:29.367617 | controller | 2025-10-14 00:16:29.451925 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-14 00:16:29.451962 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-14 00:16:29.687876 | controller | ok: Runtime: 0:00:50.145054 2025-10-14 00:16:29.695400 | 2025-10-14 00:16:29.695543 | TASK [Install pytest-forked into virtualenv] 2025-10-14 00:16:41.615564 | controller | Collecting pytest-forked 2025-10-14 00:17:05.802211 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-14 00:17:05.845466 | controller | Collecting py 2025-10-14 00:17:05.851102 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-14 00:17:05.867567 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 7.3 MB/s eta 0:00:00 2025-10-14 00:17:05.976671 | controller | Collecting pytest>=3.10 2025-10-14 00:17:05.981437 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-14 00:17:06.002823 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 19.8 MB/s eta 0:00:00 2025-10-14 00:17:06.040170 | controller | Collecting iniconfig>=1 2025-10-14 00:17:06.044304 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-14 00:17:06.085280 | controller | Collecting packaging>=20 2025-10-14 00:17:06.088784 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-14 00:17:06.094424 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 19.1 MB/s eta 0:00:00 2025-10-14 00:17:06.126293 | controller | Collecting pluggy<2,>=1.5 2025-10-14 00:17:06.130302 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-14 00:17:06.178737 | controller | Collecting pygments>=2.7.2 2025-10-14 00:17:06.182202 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-14 00:17:06.210386 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 47.9 MB/s eta 0:00:00 2025-10-14 00:17:06.281868 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-14 00:17:07.344625 | 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-14 00:17:07.358229 | controller | 2025-10-14 00:17:07.432453 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-14 00:17:07.432493 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-14 00:17:07.757424 | controller | ok: Runtime: 0:00:37.531708 2025-10-14 00:17:07.764955 | 2025-10-14 00:17:07.765073 | TASK [Update pip] 2025-10-14 00:17:08.290028 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-14 00:17:20.721930 | controller | Collecting pip 2025-10-14 00:17:33.030849 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-14 00:17:33.087157 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 34.7 MB/s eta 0:00:00 2025-10-14 00:17:33.154619 | controller | Installing collected packages: pip 2025-10-14 00:17:33.154701 | controller | Attempting uninstall: pip 2025-10-14 00:17:33.156864 | controller | Found existing installation: pip 22.2.2 2025-10-14 00:17:33.297558 | controller | Uninstalling pip-22.2.2: 2025-10-14 00:17:33.312472 | controller | Successfully uninstalled pip-22.2.2 2025-10-14 00:17:34.130383 | controller | Successfully installed pip-25.2 2025-10-14 00:17:34.313904 | controller | ok: Runtime: 0:00:26.227732 2025-10-14 00:17:34.324122 | 2025-10-14 00:17:34.324276 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-14 00:17:34.543379 | controller | changed 2025-10-14 00:17:34.552386 | 2025-10-14 00:17:34.552499 | TASK [Install ansible into virtualenv] 2025-10-14 00:17:35.112539 | controller | Processing ./src/github.com/ansible/ansible 2025-10-14 00:17:35.115899 | controller | Installing build dependencies: started 2025-10-14 00:17:57.951587 | controller | Installing build dependencies: finished with status 'done' 2025-10-14 00:17:57.952914 | controller | Getting requirements to build wheel: started 2025-10-14 00:17:58.705487 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-14 00:17:58.706850 | controller | Preparing metadata (pyproject.toml): started 2025-10-14 00:17:59.189688 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-14 00:17:59.192982 | 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-14 00:17:59.195553 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-14 00:17:59.651900 | controller | ERROR 2025-10-14 00:17:59.652037 | controller | { 2025-10-14 00:17:59.652067 | controller | "delta": "0:00:24.467870", 2025-10-14 00:17:59.652086 | controller | "end": "2025-10-14 00:17:59.271318", 2025-10-14 00:17:59.652104 | controller | "msg": "non-zero return code", 2025-10-14 00:17:59.652132 | controller | "rc": 1, 2025-10-14 00:17:59.652149 | controller | "start": "2025-10-14 00:17:34.803448" 2025-10-14 00:17:59.652169 | controller | } failure 2025-10-14 00:17:59.653842 | 2025-10-14 00:17:59.653890 | PLAY RECAP 2025-10-14 00:17:59.653930 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-14 00:17:59.653950 | 2025-10-14 00:17:59.771787 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-14 00:17:59.773361 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-14 00:18:00.386198 | 2025-10-14 00:18:00.386325 | PLAY [all] 2025-10-14 00:18:00.448377 | 2025-10-14 00:18:00.448565 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-14 00:18:00.713829 | controller | changed: non-zero return code 2025-10-14 00:18:00.727937 | 2025-10-14 00:18:00.728148 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-14 00:18:00.756205 | controller | skipping: Conditional result was False 2025-10-14 00:18:00.766116 | 2025-10-14 00:18:00.766327 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-14 00:18:00.803263 | 2025-10-14 00:18:00.803533 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-14 00:18:00.839459 | 2025-10-14 00:18:00.839665 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-14 00:18:00.865071 | controller | skipping: Conditional result was False 2025-10-14 00:18:00.873262 | 2025-10-14 00:18:00.873371 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-14 00:18:00.904042 | 2025-10-14 00:18:00.904233 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-14 00:18:00.928346 | controller | skipping: Conditional result was False 2025-10-14 00:18:00.934704 | 2025-10-14 00:18:00.934798 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-14 00:18:00.958716 | controller | skipping: Conditional result was False 2025-10-14 00:18:00.965104 | 2025-10-14 00:18:00.965181 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-14 00:18:00.989068 | controller | skipping: Conditional result was False 2025-10-14 00:18:01.017978 | 2025-10-14 00:18:01.018079 | PLAY RECAP 2025-10-14 00:18:01.018122 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-14 00:18:01.018143 | 2025-10-14 00:18:01.119151 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-14 00:18:01.120067 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-14 00:18:01.806117 | 2025-10-14 00:18:01.806253 | PLAY [all:!appliance*] 2025-10-14 00:18:01.830232 | 2025-10-14 00:18:01.830400 | TASK [unregister the node] 2025-10-14 00:18:02.366279 | controller | skipping: Conditional result was False 2025-10-14 00:18:02.381272 | 2025-10-14 00:18:02.381510 | TASK [include_role : fetch-output] 2025-10-14 00:18:02.422264 | controller | ok 2025-10-14 00:18:02.466609 | 2025-10-14 00:18:02.466781 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-14 00:18:02.523803 | controller | skipping: Conditional result was False 2025-10-14 00:18:02.537786 | 2025-10-14 00:18:02.537979 | TASK [fetch-output : Set log path for single node] 2025-10-14 00:18:02.588366 | controller | ok 2025-10-14 00:18:02.602772 | 2025-10-14 00:18:02.602973 | LOOP [fetch-output : Ensure local output dirs] 2025-10-14 00:18:03.129350 | controller -> localhost | ok: "/var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/work/logs" 2025-10-14 00:18:03.365712 | controller -> localhost | changed: "/var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/work/artifacts" 2025-10-14 00:18:03.609233 | controller -> localhost | changed: "/var/lib/zuul/builds/905e1c4b3f91496aa433a972cb8a534b/work/docs" 2025-10-14 00:18:03.631245 | 2025-10-14 00:18:03.631402 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-14 00:18:04.337953 | controller | changed: 2025-10-14 00:18:04.338237 | controller | .d..t...... ./ 2025-10-14 00:18:04.338280 | controller | cd+++++++++ controller/ 2025-10-14 00:18:04.338332 | controller | changed: All items complete 2025-10-14 00:18:04.338362 | 2025-10-14 00:18:04.806447 | controller | changed: .d..t...... ./ 2025-10-14 00:18:05.292280 | controller | changed: .d..t...... ./ 2025-10-14 00:18:05.322189 | 2025-10-14 00:18:05.322369 | TASK [include_role : fetch-output-openshift] 2025-10-14 00:18:05.350691 | controller | skipping: Conditional result was False 2025-10-14 00:18:05.367551 | 2025-10-14 00:18:05.367715 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-14 00:18:05.420830 | controller | skipping: Conditional result was False 2025-10-14 00:18:05.436012 | controller | skipping: Conditional result was False 2025-10-14 00:18:05.481506 | 2025-10-14 00:18:05.481615 | PLAY [localhost] 2025-10-14 00:18:05.502165 | 2025-10-14 00:18:05.502333 | TASK [Run Zuul manifest role] 2025-10-14 00:18:05.524708 | localhost | ok 2025-10-14 00:18:05.639247 | 2025-10-14 00:18:05.639395 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-14 00:18:05.997811 | localhost | changed 2025-10-14 00:18:06.003040 | 2025-10-14 00:18:06.003108 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-14 00:18:06.031609 | localhost | ok 2025-10-14 00:18:06.039991 | 2025-10-14 00:18:06.040060 | TASK [Set zuul-log-path fact] 2025-10-14 00:18:06.057854 | localhost | ok 2025-10-14 00:18:06.081455 | 2025-10-14 00:18:06.081560 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-14 00:18:06.110116 | localhost | ok 2025-10-14 00:18:06.118034 | 2025-10-14 00:18:06.118424 | LOOP [Run upload-logs-swift role] 2025-10-14 00:18:06.143274 | localhost | Output suppressed because no_log was given 2025-10-14 00:18:06.287313 | 2025-10-14 00:18:06.287425 | TASK [Set zuul-log-path fact] 2025-10-14 00:18:06.311453 | localhost | skipping: Conditional result was False 2025-10-14 00:18:06.317420 | 2025-10-14 00:18:06.317510 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-14 00:18:06.769830 | localhost -> localhost | ok: Runtime: 0:00:00.005253 2025-10-14 00:18:06.775334 | 2025-10-14 00:18:06.775429 | TASK [upload-logs-swift : Upload logs to swift]