2025-10-24 00:26:22.226151 | Job console starting... 2025-10-24 00:26:22.237717 | Updating repositories 2025-10-24 00:26:22.366252 | Preparing job workspace 2025-10-24 00:26:26.198832 | Running Ansible setup... 2025-10-24 00:26:33.574396 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-24 00:26:34.225724 | 2025-10-24 00:26:34.225850 | PLAY [localhost] 2025-10-24 00:26:34.234664 | 2025-10-24 00:26:34.234747 | TASK [Gathering Facts] 2025-10-24 00:26:35.241160 | localhost | ok 2025-10-24 00:26:35.255344 | 2025-10-24 00:26:35.255451 | TASK [Setup log path fact] 2025-10-24 00:26:35.273440 | localhost | ok 2025-10-24 00:26:35.286197 | 2025-10-24 00:26:35.286310 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-24 00:26:35.315613 | localhost | ok 2025-10-24 00:26:35.327454 | 2025-10-24 00:26:35.327592 | TASK [emit-job-header : Print job information] 2025-10-24 00:26:35.357991 | # Job Information 2025-10-24 00:26:35.358215 | Ansible Version: 2.15.12 2025-10-24 00:26:35.358259 | Job: ansible-test-sanity-docker-devel 2025-10-24 00:26:35.358289 | Pipeline: periodic 2025-10-24 00:26:35.358315 | Executor: ze01.softwarefactory-project.io 2025-10-24 00:26:35.358341 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-24 00:26:35.358372 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/42c/ansible/42c8e5b96c8f4174b1975528bf043308/ 2025-10-24 00:26:35.358400 | Event ID: acb2b6be1cf84e53ab9a0343da01d887 2025-10-24 00:26:35.363569 | 2025-10-24 00:26:35.363672 | LOOP [emit-job-header : Print node information] 2025-10-24 00:26:35.481856 | localhost | ok: 2025-10-24 00:26:35.482161 | localhost | # Node Information 2025-10-24 00:26:35.482233 | localhost | Inventory Hostname: controller 2025-10-24 00:26:35.482287 | localhost | Hostname: np0005500920 2025-10-24 00:26:35.482338 | localhost | Username: zuul 2025-10-24 00:26:35.482394 | localhost | Distro: Fedora 37 2025-10-24 00:26:35.482443 | localhost | Provider: ansible-vexxhost-ams1 2025-10-24 00:26:35.482491 | localhost | Region: ams1 2025-10-24 00:26:35.482535 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-24 00:26:35.482581 | localhost | Product Name: OpenStack Nova 2025-10-24 00:26:35.482626 | localhost | Interface IP: 38.129.16.148 2025-10-24 00:26:35.500403 | 2025-10-24 00:26:35.500581 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-24 00:26:35.938117 | localhost -> localhost | changed 2025-10-24 00:26:35.946775 | 2025-10-24 00:26:35.946926 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-24 00:26:36.873000 | localhost -> localhost | changed 2025-10-24 00:26:36.921166 | 2025-10-24 00:26:36.921282 | PLAY [all:!appliance*] 2025-10-24 00:26:36.945870 | 2025-10-24 00:26:36.946039 | TASK [include_role : start-zuul-console] 2025-10-24 00:26:36.968618 | controller | ok 2025-10-24 00:26:36.989468 | 2025-10-24 00:26:36.989769 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-24 00:26:37.946347 | controller | ok 2025-10-24 00:26:37.957660 | 2025-10-24 00:26:37.957770 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-24 00:26:40.305792 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-24 00:26:40.321666 | 2025-10-24 00:26:40.321827 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-24 00:26:40.694849 | controller | skipping: Conditional result was False 2025-10-24 00:26:40.708826 | 2025-10-24 00:26:40.708978 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-24 00:26:40.735770 | controller | skipping: Conditional result was False 2025-10-24 00:26:40.745816 | 2025-10-24 00:26:40.745903 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-24 00:26:40.770404 | controller | skipping: Conditional result was False 2025-10-24 00:26:40.785009 | 2025-10-24 00:26:40.785210 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-24 00:26:40.811562 | controller | skipping: Conditional result was False 2025-10-24 00:26:40.825625 | 2025-10-24 00:26:40.825772 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-24 00:26:40.852437 | controller | skipping: Conditional result was False 2025-10-24 00:26:40.865910 | 2025-10-24 00:26:40.866093 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-24 00:26:40.882738 | controller | skipping: Conditional result was False 2025-10-24 00:26:40.907810 | 2025-10-24 00:26:40.907952 | TASK [Disable Fedora Modular] 2025-10-24 00:26:42.385074 | controller | changed 2025-10-24 00:26:42.397976 | 2025-10-24 00:26:42.398183 | TASK [Enable EPEL] 2025-10-24 00:26:42.425008 | controller | skipping: Conditional result was False 2025-10-24 00:26:42.438131 | 2025-10-24 00:26:42.438323 | TASK [Register the RHEL node] 2025-10-24 00:26:42.850486 | 2025-10-24 00:26:42.850773 | TASK [Show the subscription-manager status] 2025-10-24 00:26:43.233006 | controller | skipping: Conditional result was False 2025-10-24 00:26:43.247455 | 2025-10-24 00:26:43.247610 | TASK [Enable EPEL on RHEL] 2025-10-24 00:26:43.650381 | controller | skipping: Conditional result was False 2025-10-24 00:26:43.664612 | 2025-10-24 00:26:43.664770 | TASK [Install git and tox] 2025-10-24 00:28:35.090715 | controller | changed 2025-10-24 00:28:35.099936 | 2025-10-24 00:28:35.100086 | TASK [include_role : prepare-workspace] 2025-10-24 00:28:35.138150 | controller | ok 2025-10-24 00:28:35.171827 | 2025-10-24 00:28:35.171965 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-24 00:28:35.968134 | controller | ok 2025-10-24 00:28:35.977844 | 2025-10-24 00:28:35.977913 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-24 00:28:51.387573 | controller | Output suppressed because no_log was given 2025-10-24 00:28:51.486237 | 2025-10-24 00:28:51.486385 | TASK [include_role : prepare-workspace-openshift] 2025-10-24 00:28:51.503789 | controller | skipping: Conditional result was False 2025-10-24 00:28:51.534799 | 2025-10-24 00:28:51.534902 | PLAY [all:!appliance] 2025-10-24 00:28:51.559640 | 2025-10-24 00:28:51.559779 | TASK [Run add-build-sshkey role (RSA)] 2025-10-24 00:28:51.593337 | controller | ok 2025-10-24 00:28:51.614820 | 2025-10-24 00:28:51.614956 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-24 00:28:51.897623 | controller -> localhost | ok 2025-10-24 00:28:51.911582 | 2025-10-24 00:28:51.911975 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-24 00:28:51.948168 | controller | ok 2025-10-24 00:28:51.968359 | controller | included: /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-24 00:28:51.977690 | 2025-10-24 00:28:51.977821 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-24 00:28:52.502198 | controller -> localhost | Generating public/private rsa key pair. 2025-10-24 00:28:52.502368 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/work/42c8e5b96c8f4174b1975528bf043308_id_rsa. 2025-10-24 00:28:52.502420 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/work/42c8e5b96c8f4174b1975528bf043308_id_rsa.pub. 2025-10-24 00:28:52.502445 | controller -> localhost | The key fingerprint is: 2025-10-24 00:28:52.502465 | controller -> localhost | SHA256:ovq1kyZS3uUXfwE58//JHc8YjDEtd5wOow79XqVa9sE zuul-build-sshkey 2025-10-24 00:28:52.502484 | controller -> localhost | The key's randomart image is: 2025-10-24 00:28:52.502502 | controller -> localhost | +---[RSA 2048]----+ 2025-10-24 00:28:52.502520 | controller -> localhost | | | 2025-10-24 00:28:52.502538 | controller -> localhost | | | 2025-10-24 00:28:52.502556 | controller -> localhost | | . | 2025-10-24 00:28:52.502573 | controller -> localhost | | =. ..| 2025-10-24 00:28:52.502591 | controller -> localhost | | . S +Bo.+| 2025-10-24 00:28:52.502622 | controller -> localhost | | .. .. o .BBo.| 2025-10-24 00:28:52.502644 | controller -> localhost | | o...+ . =. *E | 2025-10-24 00:28:52.502663 | controller -> localhost | | ..o.=.. + o++=B| 2025-10-24 00:28:52.502681 | controller -> localhost | | .o.o.. . .o+.oB| 2025-10-24 00:28:52.502701 | controller -> localhost | +----[SHA256]-----+ 2025-10-24 00:28:52.502744 | controller -> localhost | ok: Runtime: 0:00:00.061772 2025-10-24 00:28:52.510105 | 2025-10-24 00:28:52.510192 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-24 00:28:52.540035 | controller | ok 2025-10-24 00:28:52.549827 | controller | included: /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-24 00:28:52.558669 | 2025-10-24 00:28:52.558738 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-24 00:28:52.582730 | controller | skipping: Conditional result was False 2025-10-24 00:28:52.590968 | 2025-10-24 00:28:52.591090 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-24 00:28:53.659286 | controller | changed 2025-10-24 00:28:53.673967 | 2025-10-24 00:28:53.674188 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-24 00:28:54.285440 | controller | ok 2025-10-24 00:28:54.299272 | 2025-10-24 00:28:54.299456 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-24 00:28:57.191527 | controller | changed 2025-10-24 00:28:57.206801 | 2025-10-24 00:28:57.207046 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-24 00:29:00.106744 | controller | changed 2025-10-24 00:29:00.115397 | 2025-10-24 00:29:00.115491 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-24 00:29:00.150389 | controller | skipping: Conditional result was False 2025-10-24 00:29:00.159113 | 2025-10-24 00:29:00.159216 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-24 00:29:00.583125 | controller -> localhost | changed 2025-10-24 00:29:00.600458 | 2025-10-24 00:29:00.600576 | TASK [add-build-sshkey : Add back temp key] 2025-10-24 00:29:00.901386 | controller -> localhost | Identity added: /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/work/42c8e5b96c8f4174b1975528bf043308_id_rsa (zuul-build-sshkey) 2025-10-24 00:29:00.901581 | controller -> localhost | ok: Runtime: 0:00:00.013534 2025-10-24 00:29:00.908072 | 2025-10-24 00:29:00.908138 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-24 00:29:01.829604 | controller | ok 2025-10-24 00:29:01.835425 | 2025-10-24 00:29:01.835533 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-24 00:29:01.859584 | controller | skipping: Conditional result was False 2025-10-24 00:29:01.871321 | 2025-10-24 00:29:01.871442 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-24 00:29:01.892161 | controller | ok 2025-10-24 00:29:01.909760 | 2025-10-24 00:29:01.909874 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-24 00:29:02.168803 | controller -> localhost | ok 2025-10-24 00:29:02.177247 | 2025-10-24 00:29:02.177387 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-24 00:29:02.201861 | controller | ok 2025-10-24 00:29:02.217899 | controller | included: /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-24 00:29:02.225556 | 2025-10-24 00:29:02.225663 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-24 00:29:02.507383 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-24 00:29:02.507651 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/work/42c8e5b96c8f4174b1975528bf043308_id_ecdsa. 2025-10-24 00:29:02.507688 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/work/42c8e5b96c8f4174b1975528bf043308_id_ecdsa.pub. 2025-10-24 00:29:02.507726 | controller -> localhost | The key fingerprint is: 2025-10-24 00:29:02.507757 | controller -> localhost | SHA256:nYbYxLFwK6e/Cd5e/heFkrIWenehzDK5OAnkyAKaWUM zuul-build-sshkey 2025-10-24 00:29:02.507785 | controller -> localhost | The key's randomart image is: 2025-10-24 00:29:02.507806 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-24 00:29:02.507826 | controller -> localhost | | . o | 2025-10-24 00:29:02.507846 | controller -> localhost | | E + + | 2025-10-24 00:29:02.507864 | controller -> localhost | | . . * . . | 2025-10-24 00:29:02.507882 | controller -> localhost | |. o .B oo.o o .| 2025-10-24 00:29:02.507900 | controller -> localhost | |.= o +o S.+B o o | 2025-10-24 00:29:02.507918 | controller -> localhost | |+ . o o...B = o | 2025-10-24 00:29:02.507936 | controller -> localhost | | . ...=.= . . | 2025-10-24 00:29:02.507954 | controller -> localhost | | . o+=. . | 2025-10-24 00:29:02.507971 | controller -> localhost | | ..=..... | 2025-10-24 00:29:02.507988 | controller -> localhost | +----[SHA256]-----+ 2025-10-24 00:29:02.508061 | controller -> localhost | ok: Runtime: 0:00:00.015560 2025-10-24 00:29:02.515993 | 2025-10-24 00:29:02.516130 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-24 00:29:02.549125 | controller | ok 2025-10-24 00:29:02.558151 | controller | included: /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-24 00:29:02.568863 | 2025-10-24 00:29:02.569003 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-24 00:29:02.594257 | controller | skipping: Conditional result was False 2025-10-24 00:29:02.601301 | 2025-10-24 00:29:02.601478 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-24 00:29:03.449086 | controller | changed 2025-10-24 00:29:03.462984 | 2025-10-24 00:29:03.463238 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-24 00:29:04.078952 | controller | ok 2025-10-24 00:29:04.085916 | 2025-10-24 00:29:04.085990 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-24 00:29:06.984311 | controller | changed 2025-10-24 00:29:07.006272 | 2025-10-24 00:29:07.006507 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-24 00:29:09.916692 | controller | changed 2025-10-24 00:29:09.926968 | 2025-10-24 00:29:09.927142 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-24 00:29:09.942947 | controller | skipping: Conditional result was False 2025-10-24 00:29:09.956749 | 2025-10-24 00:29:09.956899 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-24 00:29:10.185580 | controller -> localhost | changed 2025-10-24 00:29:10.197906 | 2025-10-24 00:29:10.198010 | TASK [add-build-sshkey : Add back temp key] 2025-10-24 00:29:10.478704 | controller -> localhost | Identity added: /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/work/42c8e5b96c8f4174b1975528bf043308_id_ecdsa (zuul-build-sshkey) 2025-10-24 00:29:10.478935 | controller -> localhost | ok: Runtime: 0:00:00.007079 2025-10-24 00:29:10.485710 | 2025-10-24 00:29:10.485819 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-24 00:29:11.159451 | controller | ok 2025-10-24 00:29:11.174201 | 2025-10-24 00:29:11.174360 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-24 00:29:11.211833 | controller | skipping: Conditional result was False 2025-10-24 00:29:11.229144 | 2025-10-24 00:29:11.229261 | TASK [include_role : remove-zuul-sshkey] 2025-10-24 00:29:11.255097 | controller | skipping: Conditional result was False 2025-10-24 00:29:11.265635 | 2025-10-24 00:29:11.265742 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-24 00:29:11.892485 | controller | ok: "logs" 2025-10-24 00:29:11.892757 | controller | ok: All items complete 2025-10-24 00:29:11.892795 | 2025-10-24 00:29:12.468474 | controller | ok: "artifacts" 2025-10-24 00:29:13.060488 | controller | ok: "docs" 2025-10-24 00:29:13.085530 | 2025-10-24 00:29:13.085742 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-24 00:29:13.729789 | controller | changed: "logs" 2025-10-24 00:29:14.306543 | controller | changed: "artifacts" 2025-10-24 00:29:14.903891 | controller | changed: "docs" 2025-10-24 00:29:14.945978 | 2025-10-24 00:29:14.946100 | PLAY RECAP 2025-10-24 00:29:14.946145 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-24 00:29:14.946172 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-24 00:29:14.946192 | 2025-10-24 00:29:15.080315 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-24 00:29:15.081177 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-24 00:29:15.656399 | 2025-10-24 00:29:15.656523 | PLAY [all] 2025-10-24 00:29:15.679086 | 2025-10-24 00:29:15.679228 | TASK [Install binary dependencies] 2025-10-24 00:29:15.738495 | controller | ok 2025-10-24 00:29:15.757795 | 2025-10-24 00:29:15.757923 | TASK [bindep : Include find tasks] 2025-10-24 00:29:15.787170 | controller | ok 2025-10-24 00:29:15.794811 | controller | included: /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-24 00:29:15.801488 | 2025-10-24 00:29:15.801570 | TASK [bindep : Look for bindep.txt] 2025-10-24 00:29:16.939234 | controller | ok 2025-10-24 00:29:16.947418 | 2025-10-24 00:29:16.947530 | TASK [bindep : Define bindep_file fact] 2025-10-24 00:29:16.973705 | controller | skipping: Conditional result was False 2025-10-24 00:29:16.982681 | 2025-10-24 00:29:16.982790 | TASK [bindep : Look for other-requirements.txt] 2025-10-24 00:29:17.519227 | controller | ok 2025-10-24 00:29:17.526210 | 2025-10-24 00:29:17.526362 | TASK [bindep : Define bindep_file fact] 2025-10-24 00:29:17.561906 | controller | skipping: Conditional result was False 2025-10-24 00:29:17.568205 | 2025-10-24 00:29:17.568315 | TASK [bindep : Look for bindep fallback file] 2025-10-24 00:29:17.593046 | controller | skipping: Conditional result was False 2025-10-24 00:29:17.599478 | 2025-10-24 00:29:17.599553 | TASK [bindep : Define bindep_file fact] 2025-10-24 00:29:17.634350 | controller | skipping: Conditional result was False 2025-10-24 00:29:17.640810 | 2025-10-24 00:29:17.640885 | TASK [bindep : Include bindep tasks] 2025-10-24 00:29:17.665700 | controller | skipping: Conditional result was False 2025-10-24 00:29:17.674853 | 2025-10-24 00:29:17.674987 | TASK [bindep : Include install tasks] 2025-10-24 00:29:17.710915 | controller | skipping: Conditional result was False 2025-10-24 00:29:17.720141 | 2025-10-24 00:29:17.720251 | LOOP [bindep : Include package tasks] 2025-10-24 00:29:17.788987 | 2025-10-24 00:29:17.789351 | TASK [Run test-setup role] 2025-10-24 00:29:17.812503 | controller | ok 2025-10-24 00:29:17.831845 | 2025-10-24 00:29:17.831981 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-24 00:29:18.415288 | controller | ok 2025-10-24 00:29:18.421903 | 2025-10-24 00:29:18.421983 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-24 00:29:18.778383 | controller | skipping: Conditional result was False 2025-10-24 00:29:18.836137 | 2025-10-24 00:29:18.836317 | PLAY RECAP 2025-10-24 00:29:18.836380 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-24 00:29:18.836410 | 2025-10-24 00:29:18.945079 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-24 00:29:18.946858 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-24 00:29:19.596279 | 2025-10-24 00:29:19.596409 | PLAY [controller] 2025-10-24 00:29:19.616044 | 2025-10-24 00:29:19.616131 | TASK [Create the /root directory] 2025-10-24 00:29:20.602291 | controller | ok 2025-10-24 00:29:20.608311 | 2025-10-24 00:29:20.608387 | TASK [Install glibc-langpack-en] 2025-10-24 00:29:27.900156 | controller | ok: Nothing to do 2025-10-24 00:29:27.914268 | 2025-10-24 00:29:27.914453 | TASK [Ensure controller directory exists] 2025-10-24 00:29:28.692068 | controller | changed 2025-10-24 00:29:28.707717 | 2025-10-24 00:29:28.707893 | TASK [Install container runtime] 2025-10-24 00:29:28.785111 | controller | ok 2025-10-24 00:29:28.838537 | 2025-10-24 00:29:28.838645 | LOOP [ensure-podman : Find distribution installation] 2025-10-24 00:29:28.889755 | controller | ok: "/var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-24 00:29:28.901850 | controller | included: /var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-24 00:29:28.908623 | 2025-10-24 00:29:28.908728 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-24 00:31:20.820421 | controller | changed 2025-10-24 00:31:20.834443 | 2025-10-24 00:31:20.834644 | TASK [ensure-podman : Fetch podman version] 2025-10-24 00:31:21.957149 | controller | Client: Podman Engine 2025-10-24 00:31:22.003384 | controller | Version: 4.6.2 2025-10-24 00:31:22.003463 | controller | API Version: 4.6.2 2025-10-24 00:31:22.003472 | controller | Go Version: go1.19.12 2025-10-24 00:31:22.003496 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-24 00:31:22.003505 | controller | OS/Arch: linux/amd64 2025-10-24 00:31:22.198207 | controller | ok: Runtime: 0:00:00.276534 2025-10-24 00:31:22.213694 | 2025-10-24 00:31:22.213856 | TASK [ensure-podman : Print podman version installed] 2025-10-24 00:31:22.243353 | Podman version: Client: Podman Engine 2025-10-24 00:31:22.243605 | Version: 4.6.2 2025-10-24 00:31:22.243669 | API Version: 4.6.2 2025-10-24 00:31:22.243713 | Go Version: go1.19.12 2025-10-24 00:31:22.243755 | Built: Mon Aug 28 19:38:31 2023 2025-10-24 00:31:22.243799 | OS/Arch: linux/amd64 2025-10-24 00:31:22.257967 | 2025-10-24 00:31:22.258159 | TASK [ensure-podman : Validate podman engine] 2025-10-24 00:31:22.624265 | controller | skipping: Conditional result was False 2025-10-24 00:31:22.635258 | 2025-10-24 00:31:22.635473 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-24 00:31:22.663170 | controller | skipping: Conditional result was False 2025-10-24 00:31:22.681974 | 2025-10-24 00:31:22.682217 | TASK [Ensure python3.8 is present] 2025-10-24 00:31:22.710040 | controller | skipping: Conditional result was False 2025-10-24 00:31:22.720476 | 2025-10-24 00:31:22.720709 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-24 00:31:22.745891 | controller | ok 2025-10-24 00:31:22.776696 | 2025-10-24 00:31:22.776938 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-24 00:31:26.000706 | controller | ok: Nothing to do 2025-10-24 00:31:26.008454 | 2025-10-24 00:31:26.008533 | TASK [our-ensure-python : Also install python3-devel] 2025-10-24 00:31:39.689219 | controller | changed 2025-10-24 00:31:39.717581 | 2025-10-24 00:31:39.717728 | TASK [Run ensure-virtualenv role] 2025-10-24 00:31:39.742967 | controller | ok 2025-10-24 00:31:39.776133 | 2025-10-24 00:31:39.776289 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-24 00:31:40.541124 | controller | /usr/bin/virtualenv 2025-10-24 00:31:40.684654 | controller | ok: Runtime: 0:00:00.006330 2025-10-24 00:31:40.694797 | 2025-10-24 00:31:40.694948 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-24 00:31:40.724760 | controller | skipping: Conditional result was False 2025-10-24 00:31:40.725155 | controller | ok: All items complete 2025-10-24 00:31:40.725245 | 2025-10-24 00:31:40.749897 | 2025-10-24 00:31:40.750102 | TASK [Find the full path of the Python interpreter] 2025-10-24 00:31:41.326629 | controller | /usr/bin/python3 2025-10-24 00:31:41.615732 | controller | ok 2025-10-24 00:31:41.630796 | 2025-10-24 00:31:41.630973 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-24 00:31:43.230416 | controller | created virtual environment CPython3.11.0.final.0-64 in 763ms 2025-10-24 00:31:43.323209 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-24 00:31:43.323366 | 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-24 00:31:43.323383 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-24 00:31:43.323404 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-24 00:31:43.509128 | controller | changed 2025-10-24 00:31:43.516575 | 2025-10-24 00:31:43.516703 | TASK [Set selinux package] 2025-10-24 00:31:43.539479 | controller | ok 2025-10-24 00:31:43.547843 | 2025-10-24 00:31:43.547949 | TASK [Set selinux package (Fedora)] 2025-10-24 00:31:43.601274 | controller | ok 2025-10-24 00:31:43.608930 | 2025-10-24 00:31:43.609081 | TASK [Install selinux into virtualenv] 2025-10-24 00:31:46.445883 | controller | Collecting selinux-please-lie-to-me 2025-10-24 00:31:46.502317 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-24 00:31:46.932318 | controller | Collecting setuptools<50.0.0 2025-10-24 00:31:46.939617 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-24 00:31:46.985858 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 19.7 MB/s eta 0:00:00 2025-10-24 00:31:47.101965 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-24 00:31:47.102316 | controller | Attempting uninstall: setuptools 2025-10-24 00:31:47.106499 | controller | Found existing installation: setuptools 62.6.0 2025-10-24 00:31:47.197808 | controller | Uninstalling setuptools-62.6.0: 2025-10-24 00:31:47.210309 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-24 00:31:47.865011 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-24 00:31:48.039789 | controller | 2025-10-24 00:31:48.364946 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-24 00:31:48.365032 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-24 00:31:48.971280 | controller | ok: Runtime: 0:00:03.937282 2025-10-24 00:31:48.979706 | 2025-10-24 00:31:48.979844 | TASK [Install pytest-forked into virtualenv] 2025-10-24 00:31:50.443501 | controller | Collecting pytest-forked 2025-10-24 00:31:50.499285 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-24 00:31:50.553684 | controller | Collecting py 2025-10-24 00:31:50.559289 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-24 00:31:50.588105 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.7 MB/s eta 0:00:00 2025-10-24 00:31:50.725923 | controller | Collecting pytest>=3.10 2025-10-24 00:31:50.731197 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-24 00:31:50.747716 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 29.2 MB/s eta 0:00:00 2025-10-24 00:31:50.797134 | controller | Collecting iniconfig>=1 2025-10-24 00:31:50.802325 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-24 00:31:50.860369 | controller | Collecting packaging>=20 2025-10-24 00:31:50.865354 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-24 00:31:50.875886 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.2 MB/s eta 0:00:00 2025-10-24 00:31:50.919320 | controller | Collecting pluggy<2,>=1.5 2025-10-24 00:31:50.924090 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-24 00:31:50.989611 | controller | Collecting pygments>=2.7.2 2025-10-24 00:31:50.994464 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-24 00:31:51.017882 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 63.1 MB/s eta 0:00:00 2025-10-24 00:31:51.115031 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-24 00:31:53.230811 | controller | Successfully installed iniconfig-2.3.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-24 00:31:53.244594 | controller | 2025-10-24 00:31:53.555442 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-24 00:31:53.555525 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-24 00:31:53.860615 | controller | ok: Runtime: 0:00:03.787386 2025-10-24 00:31:53.874471 | 2025-10-24 00:31:53.874657 | TASK [Update pip] 2025-10-24 00:31:55.128136 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-24 00:31:55.370167 | controller | Collecting pip 2025-10-24 00:31:55.425871 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-24 00:31:55.478302 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 36.4 MB/s eta 0:00:00 2025-10-24 00:31:55.564429 | controller | Installing collected packages: pip 2025-10-24 00:31:55.564778 | controller | Attempting uninstall: pip 2025-10-24 00:31:55.568082 | controller | Found existing installation: pip 22.2.2 2025-10-24 00:31:55.768887 | controller | Uninstalling pip-22.2.2: 2025-10-24 00:31:55.793324 | controller | Successfully uninstalled pip-22.2.2 2025-10-24 00:31:57.379410 | controller | Successfully installed pip-25.2 2025-10-24 00:31:57.771592 | controller | ok: Runtime: 0:00:02.976500 2025-10-24 00:31:57.780457 | 2025-10-24 00:31:57.780613 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-24 00:31:58.562833 | controller | changed 2025-10-24 00:31:58.568630 | 2025-10-24 00:31:58.568756 | TASK [Install ansible into virtualenv] 2025-10-24 00:31:59.658798 | controller | Processing ./src/github.com/ansible/ansible 2025-10-24 00:31:59.664853 | controller | Installing build dependencies: started 2025-10-24 00:32:01.444097 | controller | Installing build dependencies: finished with status 'done' 2025-10-24 00:32:03.058418 | controller | Getting requirements to build wheel: started 2025-10-24 00:32:03.059266 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-24 00:32:03.915644 | controller | Preparing metadata (pyproject.toml): started 2025-10-24 00:32:03.915718 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-24 00:32:03.918971 | 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-24 00:32:03.923373 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-24 00:32:04.435416 | controller | ERROR 2025-10-24 00:32:04.435602 | controller | { 2025-10-24 00:32:04.435632 | controller | "delta": "0:00:04.975363", 2025-10-24 00:32:04.435652 | controller | "end": "2025-10-24 00:32:04.124079", 2025-10-24 00:32:04.435669 | controller | "msg": "non-zero return code", 2025-10-24 00:32:04.435700 | controller | "rc": 1, 2025-10-24 00:32:04.435717 | controller | "start": "2025-10-24 00:31:59.148716" 2025-10-24 00:32:04.435733 | controller | } failure 2025-10-24 00:32:04.437678 | 2025-10-24 00:32:04.437728 | PLAY RECAP 2025-10-24 00:32:04.437770 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-24 00:32:04.437790 | 2025-10-24 00:32:04.559907 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-24 00:32:04.560897 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-24 00:32:05.118177 | 2025-10-24 00:32:05.118319 | PLAY [all] 2025-10-24 00:32:05.139675 | 2025-10-24 00:32:05.139806 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-24 00:32:06.993571 | controller | changed: non-zero return code 2025-10-24 00:32:07.006813 | 2025-10-24 00:32:07.006996 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-24 00:32:07.034438 | controller | skipping: Conditional result was False 2025-10-24 00:32:07.048680 | 2025-10-24 00:32:07.048894 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-24 00:32:07.092383 | 2025-10-24 00:32:07.092679 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-24 00:32:07.125325 | 2025-10-24 00:32:07.125538 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-24 00:32:07.140397 | controller | skipping: Conditional result was False 2025-10-24 00:32:07.148586 | 2025-10-24 00:32:07.148744 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-24 00:32:07.171571 | 2025-10-24 00:32:07.171760 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-24 00:32:07.185996 | controller | skipping: Conditional result was False 2025-10-24 00:32:07.195614 | 2025-10-24 00:32:07.195788 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-24 00:32:07.210744 | controller | skipping: Conditional result was False 2025-10-24 00:32:07.217919 | 2025-10-24 00:32:07.218092 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-24 00:32:07.232306 | controller | skipping: Conditional result was False 2025-10-24 00:32:07.261678 | 2025-10-24 00:32:07.261782 | PLAY RECAP 2025-10-24 00:32:07.261822 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-24 00:32:07.261845 | 2025-10-24 00:32:07.373462 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-24 00:32:07.374431 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-24 00:32:07.971061 | 2025-10-24 00:32:07.971186 | PLAY [all:!appliance*] 2025-10-24 00:32:07.996471 | 2025-10-24 00:32:07.996647 | TASK [unregister the node] 2025-10-24 00:32:08.349174 | controller | skipping: Conditional result was False 2025-10-24 00:32:08.361509 | 2025-10-24 00:32:08.361681 | TASK [include_role : fetch-output] 2025-10-24 00:32:08.420956 | controller | ok 2025-10-24 00:32:08.457578 | 2025-10-24 00:32:08.457729 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-24 00:32:08.533761 | controller | skipping: Conditional result was False 2025-10-24 00:32:08.542177 | 2025-10-24 00:32:08.542286 | TASK [fetch-output : Set log path for single node] 2025-10-24 00:32:08.600060 | controller | ok 2025-10-24 00:32:08.613195 | 2025-10-24 00:32:08.613503 | LOOP [fetch-output : Ensure local output dirs] 2025-10-24 00:32:09.039210 | controller -> localhost | ok: "/var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/work/logs" 2025-10-24 00:32:09.282952 | controller -> localhost | changed: "/var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/work/artifacts" 2025-10-24 00:32:09.527635 | controller -> localhost | changed: "/var/lib/zuul/builds/42c8e5b96c8f4174b1975528bf043308/work/docs" 2025-10-24 00:32:09.541452 | 2025-10-24 00:32:09.541603 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-24 00:32:11.794924 | controller | changed: 2025-10-24 00:32:11.795585 | controller | .d..t...... ./ 2025-10-24 00:32:11.795667 | controller | cd+++++++++ controller/ 2025-10-24 00:32:11.795741 | controller | changed: All items complete 2025-10-24 00:32:11.795786 | 2025-10-24 00:32:13.846249 | controller | changed: .d..t...... ./ 2025-10-24 00:32:15.862931 | controller | changed: .d..t...... ./ 2025-10-24 00:32:15.882123 | 2025-10-24 00:32:15.882247 | TASK [include_role : fetch-output-openshift] 2025-10-24 00:32:15.906469 | controller | skipping: Conditional result was False 2025-10-24 00:32:15.912863 | 2025-10-24 00:32:15.912933 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-24 00:32:15.951766 | controller | skipping: Conditional result was False 2025-10-24 00:32:15.965862 | controller | skipping: Conditional result was False 2025-10-24 00:32:16.005238 | 2025-10-24 00:32:16.005397 | PLAY [localhost] 2025-10-24 00:32:16.023082 | 2025-10-24 00:32:16.023180 | TASK [Run Zuul manifest role] 2025-10-24 00:32:16.041451 | localhost | ok 2025-10-24 00:32:16.054389 | 2025-10-24 00:32:16.054461 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-24 00:32:16.490623 | localhost | changed 2025-10-24 00:32:16.503014 | 2025-10-24 00:32:16.503267 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-24 00:32:16.541528 | localhost | ok 2025-10-24 00:32:16.561301 | 2025-10-24 00:32:16.561499 | TASK [Set zuul-log-path fact] 2025-10-24 00:32:16.587995 | localhost | ok 2025-10-24 00:32:16.634540 | 2025-10-24 00:32:16.634665 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-24 00:32:16.674121 | localhost | ok 2025-10-24 00:32:16.682181 | 2025-10-24 00:32:16.682245 | LOOP [Run upload-logs-swift role] 2025-10-24 00:32:16.717834 | localhost | Output suppressed because no_log was given 2025-10-24 00:32:16.745843 | 2025-10-24 00:32:16.745978 | TASK [Set zuul-log-path fact] 2025-10-24 00:32:16.780344 | localhost | skipping: Conditional result was False 2025-10-24 00:32:16.789855 | 2025-10-24 00:32:16.790009 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-24 00:32:17.203580 | localhost -> localhost | ok: Runtime: 0:00:00.008404 2025-10-24 00:32:17.208934 | 2025-10-24 00:32:17.209015 | TASK [upload-logs-swift : Upload logs to swift]