2025-11-24 00:22:15.493985 | Job console starting... 2025-11-24 00:22:15.506492 | Updating repositories 2025-11-24 00:22:15.669618 | Preparing job workspace 2025-11-24 00:22:19.770429 | Running Ansible setup... 2025-11-24 00:22:27.176568 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-24 00:22:27.779370 | 2025-11-24 00:22:27.779490 | PLAY [localhost] 2025-11-24 00:22:27.788140 | 2025-11-24 00:22:27.788209 | TASK [Gathering Facts] 2025-11-24 00:22:28.775912 | localhost | ok 2025-11-24 00:22:28.809997 | 2025-11-24 00:22:28.810202 | TASK [Setup log path fact] 2025-11-24 00:22:28.832801 | localhost | ok 2025-11-24 00:22:28.846366 | 2025-11-24 00:22:28.846434 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-24 00:22:28.884418 | localhost | ok 2025-11-24 00:22:28.892335 | 2025-11-24 00:22:28.892401 | TASK [emit-job-header : Print job information] 2025-11-24 00:22:28.940656 | # Job Information 2025-11-24 00:22:28.940787 | Ansible Version: 2.15.12 2025-11-24 00:22:28.940818 | Job: ansible-test-sanity-docker-devel 2025-11-24 00:22:28.940838 | Pipeline: periodic 2025-11-24 00:22:28.940856 | Executor: ze02.softwarefactory-project.io 2025-11-24 00:22:28.940874 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-24 00:22:28.940894 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/c35/ansible/c35bac177338449785d46ebe514ed2fb/ 2025-11-24 00:22:28.940912 | Event ID: db80f5515f954e34b34bdcccc30c1493 2025-11-24 00:22:28.944660 | 2025-11-24 00:22:28.944747 | LOOP [emit-job-header : Print node information] 2025-11-24 00:22:29.063310 | localhost | ok: 2025-11-24 00:22:29.063579 | localhost | # Node Information 2025-11-24 00:22:29.063640 | localhost | Inventory Hostname: controller 2025-11-24 00:22:29.063725 | localhost | Hostname: np0005532877 2025-11-24 00:22:29.063798 | localhost | Username: zuul 2025-11-24 00:22:29.063853 | localhost | Distro: Fedora 37 2025-11-24 00:22:29.063897 | localhost | Provider: ansible-vexxhost-ams1 2025-11-24 00:22:29.063936 | localhost | Region: ams1 2025-11-24 00:22:29.063973 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-24 00:22:29.064009 | localhost | Product Name: OpenStack Nova 2025-11-24 00:22:29.064044 | localhost | Interface IP: 38.129.16.16 2025-11-24 00:22:29.079170 | 2025-11-24 00:22:29.079262 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-24 00:22:29.523469 | localhost -> localhost | changed 2025-11-24 00:22:29.535021 | 2025-11-24 00:22:29.535169 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-24 00:22:30.441251 | localhost -> localhost | changed 2025-11-24 00:22:30.483511 | 2025-11-24 00:22:30.483747 | PLAY [all:!appliance*] 2025-11-24 00:22:30.514378 | 2025-11-24 00:22:30.514463 | TASK [include_role : start-zuul-console] 2025-11-24 00:22:30.552208 | controller | ok 2025-11-24 00:22:30.574224 | 2025-11-24 00:22:30.574313 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-24 00:22:31.565288 | controller | ok 2025-11-24 00:22:31.590707 | 2025-11-24 00:22:31.590850 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-24 00:22:33.792656 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-24 00:22:33.802213 | 2025-11-24 00:22:33.802307 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-24 00:22:34.169853 | controller | skipping: Conditional result was False 2025-11-24 00:22:34.181275 | 2025-11-24 00:22:34.181432 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-24 00:22:34.218435 | controller | skipping: Conditional result was False 2025-11-24 00:22:34.227260 | 2025-11-24 00:22:34.227353 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-24 00:22:34.253525 | controller | skipping: Conditional result was False 2025-11-24 00:22:34.263821 | 2025-11-24 00:22:34.263912 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-24 00:22:34.289504 | controller | skipping: Conditional result was False 2025-11-24 00:22:34.298865 | 2025-11-24 00:22:34.298959 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-24 00:22:34.324181 | controller | skipping: Conditional result was False 2025-11-24 00:22:34.333882 | 2025-11-24 00:22:34.334047 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-24 00:22:34.362265 | controller | skipping: Conditional result was False 2025-11-24 00:22:34.384474 | 2025-11-24 00:22:34.384574 | TASK [Disable Fedora Modular] 2025-11-24 00:22:35.200371 | controller | changed 2025-11-24 00:22:35.212829 | 2025-11-24 00:22:35.212964 | TASK [Enable EPEL] 2025-11-24 00:22:35.230107 | controller | skipping: Conditional result was False 2025-11-24 00:22:35.243230 | 2025-11-24 00:22:35.243370 | TASK [Register the RHEL node] 2025-11-24 00:22:35.653087 | 2025-11-24 00:22:35.653349 | TASK [Show the subscription-manager status] 2025-11-24 00:22:36.029938 | controller | skipping: Conditional result was False 2025-11-24 00:22:36.039567 | 2025-11-24 00:22:36.039657 | TASK [Enable EPEL on RHEL] 2025-11-24 00:22:36.402623 | controller | skipping: Conditional result was False 2025-11-24 00:22:36.416288 | 2025-11-24 00:22:36.416437 | TASK [Install git and tox] 2025-11-24 00:25:10.695255 | controller | changed 2025-11-24 00:25:10.710405 | 2025-11-24 00:25:10.710541 | TASK [include_role : prepare-workspace] 2025-11-24 00:25:10.750844 | controller | ok 2025-11-24 00:25:10.788534 | 2025-11-24 00:25:10.788625 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-24 00:25:11.600059 | controller | ok 2025-11-24 00:25:11.617794 | 2025-11-24 00:25:11.617938 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-24 00:25:26.729046 | controller | Output suppressed because no_log was given 2025-11-24 00:25:26.753110 | 2025-11-24 00:25:26.753496 | TASK [include_role : prepare-workspace-openshift] 2025-11-24 00:25:26.782461 | controller | skipping: Conditional result was False 2025-11-24 00:25:26.817559 | 2025-11-24 00:25:26.817656 | PLAY [all:!appliance] 2025-11-24 00:25:26.840324 | 2025-11-24 00:25:26.840417 | TASK [Run add-build-sshkey role (RSA)] 2025-11-24 00:25:26.870803 | controller | ok 2025-11-24 00:25:26.886772 | 2025-11-24 00:25:26.886849 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-24 00:25:27.164774 | controller -> localhost | ok 2025-11-24 00:25:27.172120 | 2025-11-24 00:25:27.172193 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-24 00:25:27.203010 | controller | ok 2025-11-24 00:25:27.217068 | controller | included: /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-24 00:25:27.225093 | 2025-11-24 00:25:27.225165 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-24 00:25:27.711156 | controller -> localhost | Generating public/private rsa key pair. 2025-11-24 00:25:27.711473 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/work/c35bac177338449785d46ebe514ed2fb_id_rsa. 2025-11-24 00:25:27.711562 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/work/c35bac177338449785d46ebe514ed2fb_id_rsa.pub. 2025-11-24 00:25:27.711633 | controller -> localhost | The key fingerprint is: 2025-11-24 00:25:27.713293 | controller -> localhost | SHA256:7V//5vmwVZduXCbz/2j3eov3MHaKJRIHjNFnIRz0oFc zuul-build-sshkey 2025-11-24 00:25:27.713382 | controller -> localhost | The key's randomart image is: 2025-11-24 00:25:27.713432 | controller -> localhost | +---[RSA 2048]----+ 2025-11-24 00:25:27.713474 | controller -> localhost | | .+=.E. | 2025-11-24 00:25:27.713516 | controller -> localhost | | =o=o | 2025-11-24 00:25:27.713556 | controller -> localhost | | o +o. | 2025-11-24 00:25:27.713595 | controller -> localhost | | o . .| 2025-11-24 00:25:27.713634 | controller -> localhost | | S o . o.=| 2025-11-24 00:25:27.713720 | controller -> localhost | | . o o=+| 2025-11-24 00:25:27.713777 | controller -> localhost | | o . B++| 2025-11-24 00:25:27.713823 | controller -> localhost | | o *+%*| 2025-11-24 00:25:27.713864 | controller -> localhost | | oo*O^| 2025-11-24 00:25:27.713910 | controller -> localhost | +----[SHA256]-----+ 2025-11-24 00:25:27.714034 | controller -> localhost | ok: Runtime: 0:00:00.065738 2025-11-24 00:25:27.730973 | 2025-11-24 00:25:27.731110 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-24 00:25:27.762699 | controller | ok 2025-11-24 00:25:27.783108 | controller | included: /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-24 00:25:27.796413 | 2025-11-24 00:25:27.796499 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-24 00:25:27.821460 | controller | skipping: Conditional result was False 2025-11-24 00:25:27.831693 | 2025-11-24 00:25:27.831782 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-24 00:25:28.850565 | controller | changed 2025-11-24 00:25:28.863503 | 2025-11-24 00:25:28.863798 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-24 00:25:29.485381 | controller | ok 2025-11-24 00:25:29.498435 | 2025-11-24 00:25:29.498568 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-24 00:25:32.459902 | controller | changed 2025-11-24 00:25:32.465324 | 2025-11-24 00:25:32.465391 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-24 00:25:35.420892 | controller | changed 2025-11-24 00:25:35.426504 | 2025-11-24 00:25:35.426567 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-24 00:25:35.443795 | controller | skipping: Conditional result was False 2025-11-24 00:25:35.458846 | 2025-11-24 00:25:35.458989 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-24 00:25:35.873504 | controller -> localhost | changed 2025-11-24 00:25:35.899503 | 2025-11-24 00:25:35.899645 | TASK [add-build-sshkey : Add back temp key] 2025-11-24 00:25:36.192876 | controller -> localhost | Identity added: /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/work/c35bac177338449785d46ebe514ed2fb_id_rsa (zuul-build-sshkey) 2025-11-24 00:25:36.193233 | controller -> localhost | ok: Runtime: 0:00:00.012912 2025-11-24 00:25:36.207519 | 2025-11-24 00:25:36.207816 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-24 00:25:37.114654 | controller | ok 2025-11-24 00:25:37.127157 | 2025-11-24 00:25:37.127296 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-24 00:25:37.165399 | controller | skipping: Conditional result was False 2025-11-24 00:25:37.189851 | 2025-11-24 00:25:37.190034 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-24 00:25:37.227845 | controller | ok 2025-11-24 00:25:37.258379 | 2025-11-24 00:25:37.258475 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-24 00:25:37.568568 | controller -> localhost | ok 2025-11-24 00:25:37.587084 | 2025-11-24 00:25:37.587229 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-24 00:25:37.626331 | controller | ok 2025-11-24 00:25:37.648110 | controller | included: /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-24 00:25:37.656386 | 2025-11-24 00:25:37.656471 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-24 00:25:37.977099 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-24 00:25:37.977531 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/work/c35bac177338449785d46ebe514ed2fb_id_ecdsa. 2025-11-24 00:25:37.977591 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/work/c35bac177338449785d46ebe514ed2fb_id_ecdsa.pub. 2025-11-24 00:25:37.977650 | controller -> localhost | The key fingerprint is: 2025-11-24 00:25:37.977731 | controller -> localhost | SHA256:igYKEqI74yhv36ImHjI3fPuqYLuQpDj0JDyV79dcQzM zuul-build-sshkey 2025-11-24 00:25:37.977775 | controller -> localhost | The key's randomart image is: 2025-11-24 00:25:37.977815 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-24 00:25:37.977853 | controller -> localhost | | | 2025-11-24 00:25:37.977890 | controller -> localhost | | . | 2025-11-24 00:25:37.977927 | controller -> localhost | |o o E | 2025-11-24 00:25:37.977964 | controller -> localhost | |+.. . . o | 2025-11-24 00:25:37.978000 | controller -> localhost | |+*.. . S o | 2025-11-24 00:25:37.978036 | controller -> localhost | |B==... .o . . | 2025-11-24 00:25:37.978072 | controller -> localhost | |#o+.+... o | 2025-11-24 00:25:37.978108 | controller -> localhost | |OB=+.o. | 2025-11-24 00:25:37.978144 | controller -> localhost | |+X=+++o | 2025-11-24 00:25:37.978180 | controller -> localhost | +----[SHA256]-----+ 2025-11-24 00:25:37.978272 | controller -> localhost | ok: Runtime: 0:00:00.014316 2025-11-24 00:25:37.994377 | 2025-11-24 00:25:37.994565 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-24 00:25:38.035417 | controller | ok 2025-11-24 00:25:38.051081 | controller | included: /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-24 00:25:38.066473 | 2025-11-24 00:25:38.066616 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-24 00:25:38.092953 | controller | skipping: Conditional result was False 2025-11-24 00:25:38.107061 | 2025-11-24 00:25:38.107256 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-24 00:25:39.018794 | controller | changed 2025-11-24 00:25:39.026257 | 2025-11-24 00:25:39.026342 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-24 00:25:39.655751 | controller | ok 2025-11-24 00:25:39.668548 | 2025-11-24 00:25:39.668741 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-24 00:25:42.589032 | controller | changed 2025-11-24 00:25:42.601501 | 2025-11-24 00:25:42.601638 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-24 00:25:45.542154 | controller | changed 2025-11-24 00:25:45.555256 | 2025-11-24 00:25:45.555424 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-24 00:25:45.582126 | controller | skipping: Conditional result was False 2025-11-24 00:25:45.596711 | 2025-11-24 00:25:45.596849 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-24 00:25:45.879602 | controller -> localhost | changed 2025-11-24 00:25:45.895682 | 2025-11-24 00:25:45.895772 | TASK [add-build-sshkey : Add back temp key] 2025-11-24 00:25:46.164078 | controller -> localhost | Identity added: /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/work/c35bac177338449785d46ebe514ed2fb_id_ecdsa (zuul-build-sshkey) 2025-11-24 00:25:46.164334 | controller -> localhost | ok: Runtime: 0:00:00.009249 2025-11-24 00:25:46.173296 | 2025-11-24 00:25:46.173382 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-24 00:25:46.855443 | controller | ok 2025-11-24 00:25:46.867464 | 2025-11-24 00:25:46.867600 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-24 00:25:46.906067 | controller | skipping: Conditional result was False 2025-11-24 00:25:46.931741 | 2025-11-24 00:25:46.931892 | TASK [include_role : remove-zuul-sshkey] 2025-11-24 00:25:46.959013 | controller | skipping: Conditional result was False 2025-11-24 00:25:46.973635 | 2025-11-24 00:25:46.973813 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-24 00:25:47.609621 | controller | ok: "logs" 2025-11-24 00:25:47.610320 | controller | ok: All items complete 2025-11-24 00:25:47.610405 | 2025-11-24 00:25:48.194503 | controller | ok: "artifacts" 2025-11-24 00:25:48.772041 | controller | ok: "docs" 2025-11-24 00:25:48.788209 | 2025-11-24 00:25:48.788403 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-24 00:25:49.434111 | controller | changed: "logs" 2025-11-24 00:25:50.010990 | controller | changed: "artifacts" 2025-11-24 00:25:50.595416 | controller | changed: "docs" 2025-11-24 00:25:50.651201 | 2025-11-24 00:25:50.651377 | PLAY RECAP 2025-11-24 00:25:50.651440 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-24 00:25:50.651475 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-24 00:25:50.651499 | 2025-11-24 00:25:50.797629 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-24 00:25:50.798499 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-24 00:25:51.364848 | 2025-11-24 00:25:51.364956 | PLAY [all] 2025-11-24 00:25:51.387764 | 2025-11-24 00:25:51.387918 | TASK [Install binary dependencies] 2025-11-24 00:25:51.468938 | controller | ok 2025-11-24 00:25:51.488019 | 2025-11-24 00:25:51.488104 | TASK [bindep : Include find tasks] 2025-11-24 00:25:51.527823 | controller | ok 2025-11-24 00:25:51.535419 | controller | included: /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-24 00:25:51.541616 | 2025-11-24 00:25:51.541743 | TASK [bindep : Look for bindep.txt] 2025-11-24 00:25:52.452815 | controller | ok 2025-11-24 00:25:52.465856 | 2025-11-24 00:25:52.466028 | TASK [bindep : Define bindep_file fact] 2025-11-24 00:25:52.493541 | controller | skipping: Conditional result was False 2025-11-24 00:25:52.507168 | 2025-11-24 00:25:52.507317 | TASK [bindep : Look for other-requirements.txt] 2025-11-24 00:25:53.108205 | controller | ok 2025-11-24 00:25:53.121808 | 2025-11-24 00:25:53.121955 | TASK [bindep : Define bindep_file fact] 2025-11-24 00:25:53.159485 | controller | skipping: Conditional result was False 2025-11-24 00:25:53.172758 | 2025-11-24 00:25:53.172904 | TASK [bindep : Look for bindep fallback file] 2025-11-24 00:25:53.210283 | controller | skipping: Conditional result was False 2025-11-24 00:25:53.225029 | 2025-11-24 00:25:53.225183 | TASK [bindep : Define bindep_file fact] 2025-11-24 00:25:53.263812 | controller | skipping: Conditional result was False 2025-11-24 00:25:53.277185 | 2025-11-24 00:25:53.277327 | TASK [bindep : Include bindep tasks] 2025-11-24 00:25:53.314580 | controller | skipping: Conditional result was False 2025-11-24 00:25:53.328688 | 2025-11-24 00:25:53.328845 | TASK [bindep : Include install tasks] 2025-11-24 00:25:53.356292 | controller | skipping: Conditional result was False 2025-11-24 00:25:53.371030 | 2025-11-24 00:25:53.371185 | LOOP [bindep : Include package tasks] 2025-11-24 00:25:53.455627 | 2025-11-24 00:25:53.455926 | TASK [Run test-setup role] 2025-11-24 00:25:53.483813 | controller | ok 2025-11-24 00:25:53.514959 | 2025-11-24 00:25:53.515051 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-24 00:25:54.102923 | controller | ok 2025-11-24 00:25:54.116427 | 2025-11-24 00:25:54.116568 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-24 00:25:54.488094 | controller | skipping: Conditional result was False 2025-11-24 00:25:54.544451 | 2025-11-24 00:25:54.544542 | PLAY RECAP 2025-11-24 00:25:54.544594 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-24 00:25:54.544621 | 2025-11-24 00:25:54.657288 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-24 00:25:54.658218 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-24 00:25:55.238343 | 2025-11-24 00:25:55.238471 | PLAY [controller] 2025-11-24 00:25:55.258043 | 2025-11-24 00:25:55.258112 | TASK [Create the /root directory] 2025-11-24 00:25:56.213281 | controller | ok 2025-11-24 00:25:56.226055 | 2025-11-24 00:25:56.226228 | TASK [Install glibc-langpack-en] 2025-11-24 00:26:03.159090 | controller | ok: Nothing to do 2025-11-24 00:26:03.164782 | 2025-11-24 00:26:03.164846 | TASK [Ensure controller directory exists] 2025-11-24 00:26:03.956139 | controller | changed 2025-11-24 00:26:03.968903 | 2025-11-24 00:26:03.969037 | TASK [Install container runtime] 2025-11-24 00:26:04.051167 | controller | ok 2025-11-24 00:26:04.118180 | 2025-11-24 00:26:04.118335 | LOOP [ensure-podman : Find distribution installation] 2025-11-24 00:26:04.162334 | controller | ok: "/var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-24 00:26:04.181603 | controller | included: /var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-24 00:26:04.197949 | 2025-11-24 00:26:04.198098 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-24 00:28:04.688074 | controller | changed 2025-11-24 00:28:04.708140 | 2025-11-24 00:28:04.708287 | TASK [ensure-podman : Fetch podman version] 2025-11-24 00:28:05.787591 | controller | Client: Podman Engine 2025-11-24 00:28:05.787707 | controller | Version: 4.6.2 2025-11-24 00:28:05.787752 | controller | API Version: 4.6.2 2025-11-24 00:28:05.787794 | controller | Go Version: go1.19.12 2025-11-24 00:28:05.787847 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-24 00:28:05.787888 | controller | OS/Arch: linux/amd64 2025-11-24 00:28:06.079943 | controller | ok: Runtime: 0:00:00.238986 2025-11-24 00:28:06.093953 | 2025-11-24 00:28:06.094215 | TASK [ensure-podman : Print podman version installed] 2025-11-24 00:28:06.132930 | Podman version: Client: Podman Engine 2025-11-24 00:28:06.133180 | Version: 4.6.2 2025-11-24 00:28:06.133240 | API Version: 4.6.2 2025-11-24 00:28:06.133284 | Go Version: go1.19.12 2025-11-24 00:28:06.133324 | Built: Mon Aug 28 19:38:31 2023 2025-11-24 00:28:06.133364 | OS/Arch: linux/amd64 2025-11-24 00:28:06.145623 | 2025-11-24 00:28:06.145774 | TASK [ensure-podman : Validate podman engine] 2025-11-24 00:28:06.512234 | controller | skipping: Conditional result was False 2025-11-24 00:28:06.526358 | 2025-11-24 00:28:06.526514 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-24 00:28:06.553908 | controller | skipping: Conditional result was False 2025-11-24 00:28:06.579425 | 2025-11-24 00:28:06.579608 | TASK [Ensure python3.8 is present] 2025-11-24 00:28:06.607522 | controller | skipping: Conditional result was False 2025-11-24 00:28:06.620837 | 2025-11-24 00:28:06.620974 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-24 00:28:06.651003 | controller | ok 2025-11-24 00:28:06.685190 | 2025-11-24 00:28:06.685292 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-24 00:28:09.603635 | controller | ok: Nothing to do 2025-11-24 00:28:09.615465 | 2025-11-24 00:28:09.615599 | TASK [our-ensure-python : Also install python3-devel] 2025-11-24 00:28:23.409190 | controller | changed 2025-11-24 00:28:23.435608 | 2025-11-24 00:28:23.435716 | TASK [Run ensure-virtualenv role] 2025-11-24 00:28:23.456758 | controller | ok 2025-11-24 00:28:23.484082 | 2025-11-24 00:28:23.484207 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-24 00:28:24.238950 | controller | /usr/bin/virtualenv 2025-11-24 00:28:24.368562 | controller | ok: Runtime: 0:00:00.006737 2025-11-24 00:28:24.374229 | 2025-11-24 00:28:24.374293 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-24 00:28:24.406749 | controller | skipping: Conditional result was False 2025-11-24 00:28:24.407034 | controller | ok: All items complete 2025-11-24 00:28:24.407062 | 2025-11-24 00:28:24.435298 | 2025-11-24 00:28:24.435463 | TASK [Find the full path of the Python interpreter] 2025-11-24 00:28:25.005394 | controller | /usr/bin/python3 2025-11-24 00:28:25.294809 | controller | ok 2025-11-24 00:28:25.302899 | 2025-11-24 00:28:25.302989 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-24 00:28:26.987965 | controller | created virtual environment CPython3.11.0.final.0-64 in 807ms 2025-11-24 00:28:27.041561 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-24 00:28:27.041631 | 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-24 00:28:27.041647 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-24 00:28:27.041669 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-24 00:28:27.179656 | controller | changed 2025-11-24 00:28:27.193445 | 2025-11-24 00:28:27.193593 | TASK [Set selinux package] 2025-11-24 00:28:27.225503 | controller | ok 2025-11-24 00:28:27.237954 | 2025-11-24 00:28:27.238106 | TASK [Set selinux package (Fedora)] 2025-11-24 00:28:27.287590 | controller | ok 2025-11-24 00:28:27.301198 | 2025-11-24 00:28:27.301511 | TASK [Install selinux into virtualenv] 2025-11-24 00:28:29.887277 | controller | Collecting selinux-please-lie-to-me 2025-11-24 00:28:29.950770 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-24 00:28:30.381416 | controller | Collecting setuptools<50.0.0 2025-11-24 00:28:30.386794 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-24 00:28:30.428929 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 21.0 MB/s eta 0:00:00 2025-11-24 00:28:30.540282 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-24 00:28:30.540642 | controller | Attempting uninstall: setuptools 2025-11-24 00:28:30.544325 | controller | Found existing installation: setuptools 62.6.0 2025-11-24 00:28:30.630916 | controller | Uninstalling setuptools-62.6.0: 2025-11-24 00:28:30.644014 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-24 00:28:31.293037 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-24 00:28:31.460918 | controller | 2025-11-24 00:28:31.689871 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-24 00:28:31.689938 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-24 00:28:32.180586 | controller | ok: Runtime: 0:00:03.626657 2025-11-24 00:28:32.186454 | 2025-11-24 00:28:32.186516 | TASK [Install pytest-forked into virtualenv] 2025-11-24 00:28:33.500463 | controller | Collecting pytest-forked 2025-11-24 00:28:33.554815 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-24 00:28:33.606293 | controller | Collecting py 2025-11-24 00:28:33.611110 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-24 00:28:33.636896 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.1 MB/s eta 0:00:00 2025-11-24 00:28:33.784463 | controller | Collecting pytest>=3.10 2025-11-24 00:28:33.791626 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-11-24 00:28:33.809194 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 26.3 MB/s eta 0:00:00 2025-11-24 00:28:33.852004 | controller | Collecting iniconfig>=1.0.1 2025-11-24 00:28:33.856426 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-24 00:28:33.907138 | controller | Collecting packaging>=22 2025-11-24 00:28:33.911665 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-24 00:28:33.919443 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 12.0 MB/s eta 0:00:00 2025-11-24 00:28:33.957047 | controller | Collecting pluggy<2,>=1.5 2025-11-24 00:28:33.961214 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-24 00:28:34.019475 | controller | Collecting pygments>=2.7.2 2025-11-24 00:28:34.023738 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-24 00:28:34.044304 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 73.8 MB/s eta 0:00:00 2025-11-24 00:28:34.139112 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-24 00:28:36.047753 | 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-24 00:28:36.066885 | controller | 2025-11-24 00:28:36.266528 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-24 00:28:36.266600 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-24 00:28:36.566350 | controller | ok: Runtime: 0:00:03.345566 2025-11-24 00:28:36.579056 | 2025-11-24 00:28:36.579187 | TASK [Update pip] 2025-11-24 00:28:37.836198 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-24 00:28:38.069092 | controller | Collecting pip 2025-11-24 00:28:38.125835 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-24 00:28:38.190436 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 30.8 MB/s eta 0:00:00 2025-11-24 00:28:38.300105 | controller | Installing collected packages: pip 2025-11-24 00:28:38.300324 | controller | Attempting uninstall: pip 2025-11-24 00:28:38.303513 | controller | Found existing installation: pip 22.2.2 2025-11-24 00:28:38.503289 | controller | Uninstalling pip-22.2.2: 2025-11-24 00:28:38.526192 | controller | Successfully uninstalled pip-22.2.2 2025-11-24 00:28:40.252536 | controller | Successfully installed pip-25.3 2025-11-24 00:28:40.976824 | controller | ok: Runtime: 0:00:03.078967 2025-11-24 00:28:40.984976 | 2025-11-24 00:28:40.985078 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-24 00:28:41.834087 | controller | changed 2025-11-24 00:28:41.841277 | 2025-11-24 00:28:41.841358 | TASK [Install ansible into virtualenv] 2025-11-24 00:28:43.030646 | controller | Processing ./src/github.com/ansible/ansible 2025-11-24 00:28:43.035505 | controller | Installing build dependencies: started 2025-11-24 00:28:44.606430 | controller | Installing build dependencies: finished with status 'done' 2025-11-24 00:28:45.871304 | controller | Getting requirements to build wheel: started 2025-11-24 00:28:45.871429 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-24 00:28:46.647444 | controller | Preparing metadata (pyproject.toml): started 2025-11-24 00:28:46.647509 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-24 00:28:46.650039 | 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-24 00:28:46.653780 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-24 00:28:47.227612 | controller | ERROR 2025-11-24 00:28:47.227938 | controller | { 2025-11-24 00:28:47.228004 | controller | "delta": "0:00:04.255983", 2025-11-24 00:28:47.228049 | controller | "end": "2025-11-24 00:28:46.790915", 2025-11-24 00:28:47.228090 | controller | "msg": "non-zero return code", 2025-11-24 00:28:47.228146 | controller | "rc": 1, 2025-11-24 00:28:47.228186 | controller | "start": "2025-11-24 00:28:42.534932" 2025-11-24 00:28:47.228223 | controller | } failure 2025-11-24 00:28:47.231579 | 2025-11-24 00:28:47.231728 | PLAY RECAP 2025-11-24 00:28:47.231826 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-24 00:28:47.231882 | 2025-11-24 00:28:47.365644 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-24 00:28:47.366880 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-24 00:28:47.968451 | 2025-11-24 00:28:47.968564 | PLAY [all] 2025-11-24 00:28:47.989975 | 2025-11-24 00:28:47.990054 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-24 00:28:49.866220 | controller | changed: non-zero return code 2025-11-24 00:28:49.874748 | 2025-11-24 00:28:49.874850 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-24 00:28:49.901105 | controller | skipping: Conditional result was False 2025-11-24 00:28:49.913407 | 2025-11-24 00:28:49.913516 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-24 00:28:49.949373 | 2025-11-24 00:28:49.949542 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-24 00:28:49.984110 | 2025-11-24 00:28:49.984279 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-24 00:28:50.009455 | controller | skipping: Conditional result was False 2025-11-24 00:28:50.018448 | 2025-11-24 00:28:50.018559 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-24 00:28:50.052260 | 2025-11-24 00:28:50.052423 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-24 00:28:50.077740 | controller | skipping: Conditional result was False 2025-11-24 00:28:50.086173 | 2025-11-24 00:28:50.086265 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-24 00:28:50.111620 | controller | skipping: Conditional result was False 2025-11-24 00:28:50.119858 | 2025-11-24 00:28:50.119945 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-24 00:28:50.145502 | controller | skipping: Conditional result was False 2025-11-24 00:28:50.183318 | 2025-11-24 00:28:50.183397 | PLAY RECAP 2025-11-24 00:28:50.183450 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-24 00:28:50.183476 | 2025-11-24 00:28:50.282578 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-24 00:28:50.283477 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-24 00:28:50.858183 | 2025-11-24 00:28:50.858287 | PLAY [all:!appliance*] 2025-11-24 00:28:50.879487 | 2025-11-24 00:28:50.879583 | TASK [unregister the node] 2025-11-24 00:28:51.230076 | controller | skipping: Conditional result was False 2025-11-24 00:28:51.242491 | 2025-11-24 00:28:51.242653 | TASK [include_role : fetch-output] 2025-11-24 00:28:51.289736 | controller | ok 2025-11-24 00:28:51.315480 | 2025-11-24 00:28:51.315569 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-24 00:28:51.392226 | controller | skipping: Conditional result was False 2025-11-24 00:28:51.398659 | 2025-11-24 00:28:51.398741 | TASK [fetch-output : Set log path for single node] 2025-11-24 00:28:51.440740 | controller | ok 2025-11-24 00:28:51.448308 | 2025-11-24 00:28:51.448397 | LOOP [fetch-output : Ensure local output dirs] 2025-11-24 00:28:51.886213 | controller -> localhost | ok: "/var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/work/logs" 2025-11-24 00:28:52.159010 | controller -> localhost | changed: "/var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/work/artifacts" 2025-11-24 00:28:52.396794 | controller -> localhost | changed: "/var/lib/zuul/builds/c35bac177338449785d46ebe514ed2fb/work/docs" 2025-11-24 00:28:52.416402 | 2025-11-24 00:28:52.416540 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-24 00:28:54.659064 | controller | changed: 2025-11-24 00:28:54.659393 | controller | .d..t...... ./ 2025-11-24 00:28:54.659453 | controller | cd+++++++++ controller/ 2025-11-24 00:28:54.659569 | controller | changed: All items complete 2025-11-24 00:28:54.659769 | 2025-11-24 00:28:56.688810 | controller | changed: .d..t...... ./ 2025-11-24 00:28:58.777181 | controller | changed: .d..t...... ./ 2025-11-24 00:28:58.804784 | 2025-11-24 00:28:58.804959 | TASK [include_role : fetch-output-openshift] 2025-11-24 00:28:58.832573 | controller | skipping: Conditional result was False 2025-11-24 00:28:58.846581 | 2025-11-24 00:28:58.846758 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-24 00:28:58.894576 | controller | skipping: Conditional result was False 2025-11-24 00:28:58.912540 | controller | skipping: Conditional result was False 2025-11-24 00:28:58.972035 | 2025-11-24 00:28:58.972149 | PLAY [localhost] 2025-11-24 00:28:58.989784 | 2025-11-24 00:28:58.989868 | TASK [Run Zuul manifest role] 2025-11-24 00:28:59.008964 | localhost | ok 2025-11-24 00:28:59.021686 | 2025-11-24 00:28:59.021749 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-24 00:28:59.431416 | localhost | changed 2025-11-24 00:28:59.441143 | 2025-11-24 00:28:59.441278 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-24 00:28:59.487183 | localhost | ok 2025-11-24 00:28:59.504265 | 2025-11-24 00:28:59.504388 | TASK [Set zuul-log-path fact] 2025-11-24 00:28:59.531605 | localhost | ok 2025-11-24 00:28:59.580483 | 2025-11-24 00:28:59.580622 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-24 00:28:59.623926 | localhost | ok 2025-11-24 00:28:59.637214 | 2025-11-24 00:28:59.637298 | LOOP [Run upload-logs-swift role] 2025-11-24 00:28:59.683807 | localhost | Output suppressed because no_log was given 2025-11-24 00:28:59.727956 | 2025-11-24 00:28:59.728045 | TASK [Set zuul-log-path fact] 2025-11-24 00:28:59.753032 | localhost | skipping: Conditional result was False 2025-11-24 00:28:59.761370 | 2025-11-24 00:28:59.761460 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-24 00:29:00.193057 | localhost -> localhost | ok: Runtime: 0:00:00.005301 2025-11-24 00:29:00.204191 | 2025-11-24 00:29:00.204321 | TASK [upload-logs-swift : Upload logs to swift]