2025-09-27 00:06:34.157130 | Job console starting... 2025-09-27 00:06:34.167891 | Updating repositories 2025-09-27 00:06:34.278285 | Preparing job workspace 2025-09-27 00:06:38.106688 | Running Ansible setup... 2025-09-27 00:06:44.556712 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-27 00:06:45.185413 | 2025-09-27 00:06:45.185539 | PLAY [localhost] 2025-09-27 00:06:45.194406 | 2025-09-27 00:06:45.194498 | TASK [Gathering Facts] 2025-09-27 00:06:46.130063 | localhost | ok 2025-09-27 00:06:46.145375 | 2025-09-27 00:06:46.145538 | TASK [Setup log path fact] 2025-09-27 00:06:46.163154 | localhost | ok 2025-09-27 00:06:46.177297 | 2025-09-27 00:06:46.177406 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-27 00:06:46.205062 | localhost | ok 2025-09-27 00:06:46.212998 | 2025-09-27 00:06:46.213080 | TASK [emit-job-header : Print job information] 2025-09-27 00:06:46.242277 | # Job Information 2025-09-27 00:06:46.242834 | Ansible Version: 2.15.12 2025-09-27 00:06:46.242879 | Job: ansible-test-sanity-docker-milestone 2025-09-27 00:06:46.242906 | Pipeline: periodic 2025-09-27 00:06:46.242933 | Executor: ze03.softwarefactory-project.io 2025-09-27 00:06:46.243084 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-09-27 00:06:46.243128 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/31c/ansible/31cb3fe585454b05a9c69786d642a8dd/ 2025-09-27 00:06:46.243158 | Event ID: 6059628ede9d40b08c9c7e960ce1822b 2025-09-27 00:06:46.248407 | 2025-09-27 00:06:46.248534 | LOOP [emit-job-header : Print node information] 2025-09-27 00:06:46.361348 | localhost | ok: 2025-09-27 00:06:46.361572 | localhost | # Node Information 2025-09-27 00:06:46.361601 | localhost | Inventory Hostname: controller 2025-09-27 00:06:46.361621 | localhost | Hostname: ip-172-16-202-215 2025-09-27 00:06:46.361640 | localhost | Username: zuul-worker 2025-09-27 00:06:46.361660 | localhost | Distro: Fedora 37 2025-09-27 00:06:46.361678 | localhost | Provider: ansible-us-east-2 2025-09-27 00:06:46.361695 | localhost | Region: us-east-2 2025-09-27 00:06:46.361712 | localhost | Label: ansible-fedora-37-1vcpu 2025-09-27 00:06:46.361752 | localhost | Product Name: t3.small 2025-09-27 00:06:46.361775 | localhost | Interface IP: 18.218.1.91 2025-09-27 00:06:46.385871 | 2025-09-27 00:06:46.386130 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-27 00:06:46.777996 | localhost -> localhost | changed 2025-09-27 00:06:46.791994 | 2025-09-27 00:06:46.792156 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-27 00:06:47.770230 | localhost -> localhost | changed 2025-09-27 00:06:47.812578 | 2025-09-27 00:06:47.812683 | PLAY [all:!appliance*] 2025-09-27 00:06:47.836706 | 2025-09-27 00:06:47.836864 | TASK [include_role : start-zuul-console] 2025-09-27 00:06:47.860989 | controller | ok 2025-09-27 00:06:47.882008 | 2025-09-27 00:06:47.882133 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-27 00:06:48.567322 | controller | ok 2025-09-27 00:06:48.577700 | 2025-09-27 00:06:48.577812 | TASK [use-our-mirror : Retrieve the IP address] 2025-09-27 00:06:50.401155 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-09-27 00:06:50.408074 | 2025-09-27 00:06:50.408178 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-09-27 00:06:50.546437 | controller | skipping: Conditional result was False 2025-09-27 00:06:50.554223 | 2025-09-27 00:06:50.554334 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-09-27 00:06:50.579483 | controller | skipping: Conditional result was False 2025-09-27 00:06:50.589465 | 2025-09-27 00:06:50.589607 | TASK [use-our-mirror : Create the podman configuration directory] 2025-09-27 00:06:50.615386 | controller | skipping: Conditional result was False 2025-09-27 00:06:50.624304 | 2025-09-27 00:06:50.624461 | TASK [use-our-mirror : Copy the podman configuration] 2025-09-27 00:06:50.651386 | controller | skipping: Conditional result was False 2025-09-27 00:06:50.661828 | 2025-09-27 00:06:50.661969 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-09-27 00:06:50.689784 | controller | skipping: Conditional result was False 2025-09-27 00:06:50.697647 | 2025-09-27 00:06:50.697779 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-09-27 00:06:50.722976 | controller | skipping: Conditional result was False 2025-09-27 00:06:50.735577 | 2025-09-27 00:06:50.735672 | TASK [Disable Fedora Modular] 2025-09-27 00:06:51.504201 | controller | changed 2025-09-27 00:06:51.513117 | 2025-09-27 00:06:51.513233 | TASK [Enable EPEL] 2025-09-27 00:06:51.537261 | controller | skipping: Conditional result was False 2025-09-27 00:06:51.544216 | 2025-09-27 00:06:51.544341 | TASK [Register the RHEL node] 2025-09-27 00:06:51.689796 | 2025-09-27 00:06:51.689967 | TASK [Show the subscription-manager status] 2025-09-27 00:06:51.899131 | controller | skipping: Conditional result was False 2025-09-27 00:06:51.905469 | 2025-09-27 00:06:51.905536 | TASK [Enable EPEL on RHEL] 2025-09-27 00:06:52.057237 | controller | skipping: Conditional result was False 2025-09-27 00:06:52.066690 | 2025-09-27 00:06:52.066833 | TASK [Install git and tox] 2025-09-27 00:08:22.621921 | controller | changed 2025-09-27 00:08:22.631795 | 2025-09-27 00:08:22.631923 | TASK [include_role : prepare-workspace] 2025-09-27 00:08:22.666631 | controller | ok 2025-09-27 00:08:22.701519 | 2025-09-27 00:08:22.701674 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-27 00:08:23.238291 | controller | ok 2025-09-27 00:08:23.248042 | 2025-09-27 00:08:23.248194 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-27 00:08:37.294380 | controller | Output suppressed because no_log was given 2025-09-27 00:08:37.304336 | 2025-09-27 00:08:37.304430 | TASK [include_role : prepare-workspace-openshift] 2025-09-27 00:08:37.328775 | controller | skipping: Conditional result was False 2025-09-27 00:08:37.348922 | 2025-09-27 00:08:37.348989 | PLAY [all:!appliance] 2025-09-27 00:08:37.363798 | 2025-09-27 00:08:37.363893 | TASK [Run add-build-sshkey role (RSA)] 2025-09-27 00:08:37.435910 | controller | ok 2025-09-27 00:08:37.452821 | 2025-09-27 00:08:37.452932 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-27 00:08:37.670788 | controller -> localhost | ok 2025-09-27 00:08:37.686408 | 2025-09-27 00:08:37.686601 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-27 00:08:37.725545 | controller | ok 2025-09-27 00:08:37.752504 | controller | included: /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-27 00:08:37.762412 | 2025-09-27 00:08:37.762514 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-27 00:08:38.332083 | controller -> localhost | Generating public/private rsa key pair. 2025-09-27 00:08:38.332551 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/work/31cb3fe585454b05a9c69786d642a8dd_id_rsa. 2025-09-27 00:08:38.332629 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/work/31cb3fe585454b05a9c69786d642a8dd_id_rsa.pub. 2025-09-27 00:08:38.332687 | controller -> localhost | The key fingerprint is: 2025-09-27 00:08:38.332785 | controller -> localhost | SHA256:REbK0DGDWuEwQP6fOYASnK+LgrJaAKq3v0T905QAv9g zuul-build-sshkey 2025-09-27 00:08:38.332847 | controller -> localhost | The key's randomart image is: 2025-09-27 00:08:38.332899 | controller -> localhost | +---[RSA 2048]----+ 2025-09-27 00:08:38.332949 | controller -> localhost | |ooo o+=o+ | 2025-09-27 00:08:38.333002 | controller -> localhost | |o .+oo.O | 2025-09-27 00:08:38.333057 | controller -> localhost | |o+ o. o + | 2025-09-27 00:08:38.333109 | controller -> localhost | |o.= . + o . | 2025-09-27 00:08:38.333162 | controller -> localhost | |+. +. o E o | 2025-09-27 00:08:38.333232 | controller -> localhost | |o...o o. o | 2025-09-27 00:08:38.333295 | controller -> localhost | |o.o .= o . | 2025-09-27 00:08:38.333354 | controller -> localhost | |=o.o . . | 2025-09-27 00:08:38.333413 | controller -> localhost | |Bo..o. | 2025-09-27 00:08:38.333476 | controller -> localhost | +----[SHA256]-----+ 2025-09-27 00:08:38.333596 | controller -> localhost | ok: Runtime: 0:00:00.101022 2025-09-27 00:08:38.350260 | 2025-09-27 00:08:38.350412 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-27 00:08:38.392137 | controller | ok 2025-09-27 00:08:38.416720 | controller | included: /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-27 00:08:38.430167 | 2025-09-27 00:08:38.430254 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-27 00:08:38.455434 | controller | skipping: Conditional result was False 2025-09-27 00:08:38.466015 | 2025-09-27 00:08:38.466109 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-27 00:08:39.109676 | controller | changed 2025-09-27 00:08:39.124906 | 2025-09-27 00:08:39.125384 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-27 00:08:39.479389 | controller | ok 2025-09-27 00:08:39.495642 | 2025-09-27 00:08:39.495856 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-27 00:08:41.047371 | controller | changed 2025-09-27 00:08:41.058393 | 2025-09-27 00:08:41.058602 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-27 00:08:42.347797 | controller | changed 2025-09-27 00:08:42.356745 | 2025-09-27 00:08:42.356879 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-27 00:08:42.373566 | controller | skipping: Conditional result was False 2025-09-27 00:08:42.382269 | 2025-09-27 00:08:42.382401 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-27 00:08:42.697975 | controller -> localhost | changed 2025-09-27 00:08:42.725094 | 2025-09-27 00:08:42.725235 | TASK [add-build-sshkey : Add back temp key] 2025-09-27 00:08:43.037966 | controller -> localhost | Identity added: /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/work/31cb3fe585454b05a9c69786d642a8dd_id_rsa (zuul-build-sshkey) 2025-09-27 00:08:43.038155 | controller -> localhost | ok: Runtime: 0:00:00.008469 2025-09-27 00:08:43.044397 | 2025-09-27 00:08:43.044466 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-27 00:08:43.555465 | controller | ok 2025-09-27 00:08:43.563978 | 2025-09-27 00:08:43.564102 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-27 00:08:43.590265 | controller | skipping: Conditional result was False 2025-09-27 00:08:43.604580 | 2025-09-27 00:08:43.604752 | TASK [Run add-build-sshkey role (ECDSA)] 2025-09-27 00:08:43.625377 | controller | ok 2025-09-27 00:08:43.648757 | 2025-09-27 00:08:43.648866 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-27 00:08:43.912123 | controller -> localhost | ok 2025-09-27 00:08:43.925907 | 2025-09-27 00:08:43.926087 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-27 00:08:43.950655 | controller | ok 2025-09-27 00:08:43.967173 | controller | included: /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-27 00:08:43.979037 | 2025-09-27 00:08:43.979174 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-27 00:08:44.264598 | controller -> localhost | Generating public/private ecdsa key pair. 2025-09-27 00:08:44.264804 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/work/31cb3fe585454b05a9c69786d642a8dd_id_ecdsa. 2025-09-27 00:08:44.264841 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/work/31cb3fe585454b05a9c69786d642a8dd_id_ecdsa.pub. 2025-09-27 00:08:44.264873 | controller -> localhost | The key fingerprint is: 2025-09-27 00:08:44.264896 | controller -> localhost | SHA256:163EZyHJMDKQ2bHYx7TyLwiteyMctKtQkDLjfHWAXMk zuul-build-sshkey 2025-09-27 00:08:44.264917 | controller -> localhost | The key's randomart image is: 2025-09-27 00:08:44.264937 | controller -> localhost | +---[ECDSA 521]---+ 2025-09-27 00:08:44.264957 | controller -> localhost | | . +oo=+.+ | 2025-09-27 00:08:44.264977 | controller -> localhost | | + E+o.* = . | 2025-09-27 00:08:44.264997 | controller -> localhost | |+ o ...+ + + . | 2025-09-27 00:08:44.265016 | controller -> localhost | |o+ .. o. + o o . | 2025-09-27 00:08:44.265034 | controller -> localhost | | o .....S o + + | 2025-09-27 00:08:44.265053 | controller -> localhost | | .. oo o o + | 2025-09-27 00:08:44.265072 | controller -> localhost | | . ..o. . o | 2025-09-27 00:08:44.265091 | controller -> localhost | | . +.o . | 2025-09-27 00:08:44.265110 | controller -> localhost | | ...o . | 2025-09-27 00:08:44.265129 | controller -> localhost | +----[SHA256]-----+ 2025-09-27 00:08:44.265177 | controller -> localhost | ok: Runtime: 0:00:00.015106 2025-09-27 00:08:44.274174 | 2025-09-27 00:08:44.274294 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-27 00:08:44.307791 | controller | ok 2025-09-27 00:08:44.319568 | controller | included: /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-27 00:08:44.334609 | 2025-09-27 00:08:44.334756 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-27 00:08:44.351052 | controller | skipping: Conditional result was False 2025-09-27 00:08:44.360994 | 2025-09-27 00:08:44.361104 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-27 00:08:44.827961 | controller | changed 2025-09-27 00:08:44.837401 | 2025-09-27 00:08:44.837502 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-27 00:08:45.250355 | controller | ok 2025-09-27 00:08:45.264615 | 2025-09-27 00:08:45.264829 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-27 00:08:46.628019 | controller | changed 2025-09-27 00:08:46.641761 | 2025-09-27 00:08:46.641927 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-27 00:08:47.926936 | controller | changed 2025-09-27 00:08:47.933072 | 2025-09-27 00:08:47.933140 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-27 00:08:47.958137 | controller | skipping: Conditional result was False 2025-09-27 00:08:47.965698 | 2025-09-27 00:08:47.965819 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-27 00:08:48.288571 | controller -> localhost | changed 2025-09-27 00:08:48.301787 | 2025-09-27 00:08:48.301914 | TASK [add-build-sshkey : Add back temp key] 2025-09-27 00:08:48.635313 | controller -> localhost | Identity added: /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/work/31cb3fe585454b05a9c69786d642a8dd_id_ecdsa (zuul-build-sshkey) 2025-09-27 00:08:48.635526 | controller -> localhost | ok: Runtime: 0:00:00.021593 2025-09-27 00:08:48.641671 | 2025-09-27 00:08:48.641897 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-27 00:08:49.008527 | controller | ok 2025-09-27 00:08:49.022562 | 2025-09-27 00:08:49.022674 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-27 00:08:49.058743 | controller | skipping: Conditional result was False 2025-09-27 00:08:49.081763 | 2025-09-27 00:08:49.081903 | TASK [include_role : remove-zuul-sshkey] 2025-09-27 00:08:49.107949 | controller | skipping: Conditional result was False 2025-09-27 00:08:49.120165 | 2025-09-27 00:08:49.120319 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-27 00:08:49.484589 | controller | ok: "logs" 2025-09-27 00:08:49.484825 | controller | ok: All items complete 2025-09-27 00:08:49.484857 | 2025-09-27 00:08:49.767038 | controller | ok: "artifacts" 2025-09-27 00:08:50.050178 | controller | ok: "docs" 2025-09-27 00:08:50.072005 | 2025-09-27 00:08:50.072152 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-27 00:08:50.405449 | controller | changed: "logs" 2025-09-27 00:08:50.686886 | controller | changed: "artifacts" 2025-09-27 00:08:50.961664 | controller | changed: "docs" 2025-09-27 00:08:51.017721 | 2025-09-27 00:08:51.017881 | PLAY RECAP 2025-09-27 00:08:51.017945 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-09-27 00:08:51.017984 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-27 00:08:51.018011 | 2025-09-27 00:08:51.159211 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-27 00:08:51.160058 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-27 00:08:51.753218 | 2025-09-27 00:08:51.753339 | PLAY [all] 2025-09-27 00:08:51.775558 | 2025-09-27 00:08:51.775674 | TASK [Install binary dependencies] 2025-09-27 00:08:51.846813 | controller | ok 2025-09-27 00:08:51.866697 | 2025-09-27 00:08:51.866828 | TASK [bindep : Include find tasks] 2025-09-27 00:08:51.908270 | controller | ok 2025-09-27 00:08:51.920522 | controller | included: /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-27 00:08:51.928156 | 2025-09-27 00:08:51.928267 | TASK [bindep : Look for bindep.txt] 2025-09-27 00:08:52.470489 | controller | ok 2025-09-27 00:08:52.477289 | 2025-09-27 00:08:52.477400 | TASK [bindep : Define bindep_file fact] 2025-09-27 00:08:52.502421 | controller | skipping: Conditional result was False 2025-09-27 00:08:52.513357 | 2025-09-27 00:08:52.513519 | TASK [bindep : Look for other-requirements.txt] 2025-09-27 00:08:52.852819 | controller | ok 2025-09-27 00:08:52.861768 | 2025-09-27 00:08:52.861981 | TASK [bindep : Define bindep_file fact] 2025-09-27 00:08:52.901401 | controller | skipping: Conditional result was False 2025-09-27 00:08:52.911019 | 2025-09-27 00:08:52.911285 | TASK [bindep : Look for bindep fallback file] 2025-09-27 00:08:52.951015 | controller | skipping: Conditional result was False 2025-09-27 00:08:52.959152 | 2025-09-27 00:08:52.959291 | TASK [bindep : Define bindep_file fact] 2025-09-27 00:08:52.984098 | controller | skipping: Conditional result was False 2025-09-27 00:08:52.993265 | 2025-09-27 00:08:52.993368 | TASK [bindep : Include bindep tasks] 2025-09-27 00:08:53.029610 | controller | skipping: Conditional result was False 2025-09-27 00:08:53.041164 | 2025-09-27 00:08:53.041321 | TASK [bindep : Include install tasks] 2025-09-27 00:08:53.066511 | controller | skipping: Conditional result was False 2025-09-27 00:08:53.073555 | 2025-09-27 00:08:53.073636 | LOOP [bindep : Include package tasks] 2025-09-27 00:08:53.142998 | 2025-09-27 00:08:53.143166 | TASK [Run test-setup role] 2025-09-27 00:08:53.163184 | controller | ok 2025-09-27 00:08:53.189977 | 2025-09-27 00:08:53.190123 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-27 00:08:53.494130 | controller | ok 2025-09-27 00:08:53.505287 | 2025-09-27 00:08:53.505411 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-27 00:08:53.655353 | controller | skipping: Conditional result was False 2025-09-27 00:08:53.683706 | 2025-09-27 00:08:53.683895 | PLAY RECAP 2025-09-27 00:08:53.683963 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-27 00:08:53.684006 | 2025-09-27 00:08:53.803542 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-27 00:08:53.804493 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-27 00:08:54.412843 | 2025-09-27 00:08:54.413000 | PLAY [controller] 2025-09-27 00:08:54.434764 | 2025-09-27 00:08:54.434896 | TASK [Create the /root directory] 2025-09-27 00:08:55.191685 | controller | ok 2025-09-27 00:08:55.200611 | 2025-09-27 00:08:55.200720 | TASK [Install glibc-langpack-en] 2025-09-27 00:09:03.250839 | controller | ok: Nothing to do 2025-09-27 00:09:03.257582 | 2025-09-27 00:09:03.257688 | TASK [Ensure controller directory exists] 2025-09-27 00:09:03.748381 | controller | changed 2025-09-27 00:09:03.761504 | 2025-09-27 00:09:03.761661 | TASK [Install container runtime] 2025-09-27 00:09:03.821077 | controller | ok 2025-09-27 00:09:03.881913 | 2025-09-27 00:09:03.882061 | LOOP [ensure-podman : Find distribution installation] 2025-09-27 00:09:03.912766 | controller | ok: "/var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-09-27 00:09:03.924416 | controller | included: /var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-09-27 00:09:03.935718 | 2025-09-27 00:09:03.935893 | TASK [ensure-podman : Install podman (RedHat)] 2025-09-27 00:10:19.358047 | controller | changed 2025-09-27 00:10:19.372206 | 2025-09-27 00:10:19.372424 | TASK [ensure-podman : Fetch podman version] 2025-09-27 00:10:20.177975 | controller | Client: Podman Engine 2025-09-27 00:10:20.208303 | controller | Version: 4.6.2 2025-09-27 00:10:20.208345 | controller | API Version: 4.6.2 2025-09-27 00:10:20.208353 | controller | Go Version: go1.19.12 2025-09-27 00:10:20.208371 | controller | Built: Mon Aug 28 19:38:31 2023 2025-09-27 00:10:20.208387 | controller | OS/Arch: linux/amd64 2025-09-27 00:10:20.526229 | controller | ok: Runtime: 0:00:00.231898 2025-09-27 00:10:20.533279 | 2025-09-27 00:10:20.533367 | TASK [ensure-podman : Print podman version installed] 2025-09-27 00:10:20.564933 | Podman version: Client: Podman Engine 2025-09-27 00:10:20.565203 | Version: 4.6.2 2025-09-27 00:10:20.565235 | API Version: 4.6.2 2025-09-27 00:10:20.565257 | Go Version: go1.19.12 2025-09-27 00:10:20.565276 | Built: Mon Aug 28 19:38:31 2023 2025-09-27 00:10:20.565297 | OS/Arch: linux/amd64 2025-09-27 00:10:20.571329 | 2025-09-27 00:10:20.571417 | TASK [ensure-podman : Validate podman engine] 2025-09-27 00:10:20.756049 | controller | skipping: Conditional result was False 2025-09-27 00:10:20.762944 | 2025-09-27 00:10:20.763043 | TASK [ensure-podman : Set up docker compatability socket] 2025-09-27 00:10:20.797775 | controller | skipping: Conditional result was False 2025-09-27 00:10:20.810026 | 2025-09-27 00:10:20.816678 | TASK [Ensure python3.8 is present] 2025-09-27 00:10:20.852269 | controller | skipping: Conditional result was False 2025-09-27 00:10:20.862427 | 2025-09-27 00:10:20.862539 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-09-27 00:10:20.918350 | controller | ok 2025-09-27 00:10:20.966975 | 2025-09-27 00:10:20.967102 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-09-27 00:10:24.847609 | controller | ok: Nothing to do 2025-09-27 00:10:24.861001 | 2025-09-27 00:10:24.861157 | TASK [our-ensure-python : Also install python3-devel] 2025-09-27 00:10:37.817589 | controller | changed 2025-09-27 00:10:37.836399 | 2025-09-27 00:10:37.836553 | TASK [Run ensure-virtualenv role] 2025-09-27 00:10:37.856680 | controller | ok 2025-09-27 00:10:37.879779 | 2025-09-27 00:10:37.879874 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-09-27 00:10:38.255445 | controller | /usr/bin/virtualenv 2025-09-27 00:10:38.517599 | controller | ok: Runtime: 0:00:00.004275 2025-09-27 00:10:38.532606 | 2025-09-27 00:10:38.532832 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-09-27 00:10:38.581889 | controller | skipping: Conditional result was False 2025-09-27 00:10:38.582282 | controller | ok: All items complete 2025-09-27 00:10:38.582318 | 2025-09-27 00:10:38.609902 | 2025-09-27 00:10:38.610032 | TASK [Find the full path of the Python interpreter] 2025-09-27 00:10:39.070751 | controller | /usr/bin/python3 2025-09-27 00:10:39.287769 | controller | ok 2025-09-27 00:10:39.293749 | 2025-09-27 00:10:39.293822 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-09-27 00:10:40.713775 | controller | created virtual environment CPython3.11.0.final.0-64 in 766ms 2025-09-27 00:10:40.757005 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-09-27 00:10:40.757064 | 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-worker/.local/share/virtualenv) 2025-09-27 00:10:40.757082 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-09-27 00:10:40.757103 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-09-27 00:10:40.933966 | controller | changed 2025-09-27 00:10:40.949162 | 2025-09-27 00:10:40.949290 | TASK [Set selinux package] 2025-09-27 00:10:40.986304 | controller | ok 2025-09-27 00:10:40.994774 | 2025-09-27 00:10:40.994989 | TASK [Set selinux package (Fedora)] 2025-09-27 00:10:41.063065 | controller | ok 2025-09-27 00:10:41.073189 | 2025-09-27 00:10:41.073333 | TASK [Install selinux into virtualenv] 2025-09-27 00:10:43.663905 | controller | Collecting selinux-please-lie-to-me 2025-09-27 00:10:43.758241 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-09-27 00:10:44.287402 | controller | Collecting setuptools<50.0.0 2025-09-27 00:10:44.302851 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-09-27 00:10:44.424485 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.1 MB/s eta 0:00:00 2025-09-27 00:10:44.574708 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-09-27 00:10:44.575030 | controller | Attempting uninstall: setuptools 2025-09-27 00:10:44.579810 | controller | Found existing installation: setuptools 62.6.0 2025-09-27 00:10:44.691759 | controller | Uninstalling setuptools-62.6.0: 2025-09-27 00:10:44.706986 | controller | Successfully uninstalled setuptools-62.6.0 2025-09-27 00:10:45.455958 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-09-27 00:10:45.661612 | controller | 2025-09-27 00:10:45.871164 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-27 00:10:45.871207 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-27 00:10:46.256107 | controller | ok: Runtime: 0:00:04.312709 2025-09-27 00:10:46.262641 | 2025-09-27 00:10:46.262802 | TASK [Install pytest-forked into virtualenv] 2025-09-27 00:10:47.500571 | controller | Collecting pytest-forked 2025-09-27 00:10:47.584523 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-09-27 00:10:47.644645 | controller | Collecting py 2025-09-27 00:10:47.656455 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-09-27 00:10:47.693118 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00 2025-09-27 00:10:47.868512 | controller | Collecting pytest>=3.10 2025-09-27 00:10:47.881325 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-09-27 00:10:47.942942 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.2 MB/s eta 0:00:00 2025-09-27 00:10:47.996600 | controller | Collecting iniconfig>=1 2025-09-27 00:10:48.014341 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-09-27 00:10:48.081239 | controller | Collecting packaging>=20 2025-09-27 00:10:48.094296 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-09-27 00:10:48.106372 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.8 MB/s eta 0:00:00 2025-09-27 00:10:48.151602 | controller | Collecting pluggy<2,>=1.5 2025-09-27 00:10:48.163347 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-09-27 00:10:48.236562 | controller | Collecting pygments>=2.7.2 2025-09-27 00:10:48.248435 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-09-27 00:10:48.368995 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.4 MB/s eta 0:00:00 2025-09-27 00:10:48.502271 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-09-27 00:10:50.747425 | 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-09-27 00:10:50.763410 | controller | 2025-09-27 00:10:50.941676 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-27 00:10:50.941721 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-27 00:10:51.465209 | controller | ok: Runtime: 0:00:04.169705 2025-09-27 00:10:51.479220 | 2025-09-27 00:10:51.479432 | TASK [Update pip] 2025-09-27 00:10:52.598142 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-09-27 00:10:52.854444 | controller | Collecting pip 2025-09-27 00:10:52.952449 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-09-27 00:10:53.112172 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.3 MB/s eta 0:00:00 2025-09-27 00:10:53.277512 | controller | Installing collected packages: pip 2025-09-27 00:10:53.277941 | controller | Attempting uninstall: pip 2025-09-27 00:10:53.282455 | controller | Found existing installation: pip 22.2.2 2025-09-27 00:10:53.551698 | controller | Uninstalling pip-22.2.2: 2025-09-27 00:10:53.581247 | controller | Successfully uninstalled pip-22.2.2 2025-09-27 00:10:55.332523 | controller | Successfully installed pip-25.2 2025-09-27 00:10:55.660469 | controller | ok: Runtime: 0:00:03.521551 2025-09-27 00:10:55.669277 | 2025-09-27 00:10:55.669394 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-09-27 00:10:56.206982 | controller | changed 2025-09-27 00:10:56.219365 | 2025-09-27 00:10:56.219638 | TASK [Install ansible into virtualenv] 2025-09-27 00:10:57.264241 | controller | Processing ./src/github.com/ansible/ansible 2025-09-27 00:10:57.270843 | controller | Installing build dependencies: started 2025-09-27 00:10:59.165348 | controller | Installing build dependencies: finished with status 'done' 2025-09-27 00:11:00.693215 | controller | Getting requirements to build wheel: started 2025-09-27 00:11:00.693280 | controller | Getting requirements to build wheel: finished with status 'done' 2025-09-27 00:11:01.618804 | controller | Preparing metadata (pyproject.toml): started 2025-09-27 00:11:01.618860 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-09-27 00:11:01.622782 | 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-09-27 00:11:01.622834 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-09-27 00:11:01.877510 | controller | ERROR 2025-09-27 00:11:01.877665 | controller | { 2025-09-27 00:11:01.877696 | controller | "delta": "0:00:05.131191", 2025-09-27 00:11:01.877716 | controller | "end": "2025-09-27 00:11:01.778054", 2025-09-27 00:11:01.877780 | controller | "msg": "non-zero return code", 2025-09-27 00:11:01.877813 | controller | "rc": 1, 2025-09-27 00:11:01.877831 | controller | "start": "2025-09-27 00:10:56.646863" 2025-09-27 00:11:01.877848 | controller | } failure 2025-09-27 00:11:01.879706 | 2025-09-27 00:11:01.879772 | PLAY RECAP 2025-09-27 00:11:01.879817 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-09-27 00:11:01.879838 | 2025-09-27 00:11:02.008592 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-27 00:11:02.009822 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-27 00:11:02.618190 | 2025-09-27 00:11:02.618324 | PLAY [all] 2025-09-27 00:11:02.640482 | 2025-09-27 00:11:02.640629 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-27 00:11:03.487674 | controller | changed: non-zero return code 2025-09-27 00:11:03.493707 | 2025-09-27 00:11:03.493821 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-27 00:11:03.508095 | controller | skipping: Conditional result was False 2025-09-27 00:11:03.515051 | 2025-09-27 00:11:03.515154 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-27 00:11:03.539952 | 2025-09-27 00:11:03.540211 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-27 00:11:03.576677 | 2025-09-27 00:11:03.576908 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-27 00:11:03.602189 | controller | skipping: Conditional result was False 2025-09-27 00:11:03.608613 | 2025-09-27 00:11:03.608685 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-27 00:11:03.631707 | 2025-09-27 00:11:03.632077 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-27 00:11:03.656434 | controller | skipping: Conditional result was False 2025-09-27 00:11:03.663101 | 2025-09-27 00:11:03.663210 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-27 00:11:03.677652 | controller | skipping: Conditional result was False 2025-09-27 00:11:03.684860 | 2025-09-27 00:11:03.684979 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-27 00:11:03.699630 | controller | skipping: Conditional result was False 2025-09-27 00:11:03.729798 | 2025-09-27 00:11:03.729902 | PLAY RECAP 2025-09-27 00:11:03.729958 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-27 00:11:03.729988 | 2025-09-27 00:11:03.841076 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-27 00:11:03.842261 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-09-27 00:11:04.533795 | 2025-09-27 00:11:04.533957 | PLAY [all:!appliance*] 2025-09-27 00:11:04.561087 | 2025-09-27 00:11:04.561255 | TASK [unregister the node] 2025-09-27 00:11:04.698582 | controller | skipping: Conditional result was False 2025-09-27 00:11:04.707221 | 2025-09-27 00:11:04.707391 | TASK [include_role : fetch-output] 2025-09-27 00:11:04.738151 | controller | ok 2025-09-27 00:11:04.764650 | 2025-09-27 00:11:04.764817 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-27 00:11:04.810573 | controller | skipping: Conditional result was False 2025-09-27 00:11:04.817853 | 2025-09-27 00:11:04.817997 | TASK [fetch-output : Set log path for single node] 2025-09-27 00:11:04.851846 | controller | ok 2025-09-27 00:11:04.861129 | 2025-09-27 00:11:04.861255 | LOOP [fetch-output : Ensure local output dirs] 2025-09-27 00:11:05.348329 | controller -> localhost | ok: "/var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/work/logs" 2025-09-27 00:11:05.570012 | controller -> localhost | changed: "/var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/work/artifacts" 2025-09-27 00:11:05.789009 | controller -> localhost | changed: "/var/lib/zuul/builds/31cb3fe585454b05a9c69786d642a8dd/work/docs" 2025-09-27 00:11:05.805835 | 2025-09-27 00:11:05.806048 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-27 00:11:07.078921 | controller | changed: 2025-09-27 00:11:07.079185 | controller | .d..t...... ./ 2025-09-27 00:11:07.079225 | controller | cd+++++++++ controller/ 2025-09-27 00:11:07.079275 | controller | changed: All items complete 2025-09-27 00:11:07.079304 | 2025-09-27 00:11:08.082612 | controller | changed: .d..t...... ./ 2025-09-27 00:11:09.253463 | controller | changed: .d..t...... ./ 2025-09-27 00:11:09.280817 | 2025-09-27 00:11:09.280981 | TASK [include_role : fetch-output-openshift] 2025-09-27 00:11:09.307524 | controller | skipping: Conditional result was False 2025-09-27 00:11:09.321543 | 2025-09-27 00:11:09.321791 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-27 00:11:09.367748 | controller | skipping: Conditional result was False 2025-09-27 00:11:09.386248 | controller | skipping: Conditional result was False 2025-09-27 00:11:09.438015 | 2025-09-27 00:11:09.438220 | PLAY [localhost] 2025-09-27 00:11:09.461004 | 2025-09-27 00:11:09.461150 | TASK [Run Zuul manifest role] 2025-09-27 00:11:09.482630 | localhost | ok 2025-09-27 00:11:09.499453 | 2025-09-27 00:11:09.499585 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-27 00:11:09.973099 | localhost | changed 2025-09-27 00:11:09.980537 | 2025-09-27 00:11:09.980648 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-27 00:11:10.024193 | localhost | ok 2025-09-27 00:11:10.032908 | 2025-09-27 00:11:10.032998 | TASK [Set zuul-log-path fact] 2025-09-27 00:11:10.052279 | localhost | ok 2025-09-27 00:11:10.071002 | 2025-09-27 00:11:10.071109 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-27 00:11:10.111939 | localhost | ok 2025-09-27 00:11:10.121873 | 2025-09-27 00:11:10.121977 | LOOP [Run upload-logs-swift role] 2025-09-27 00:11:10.157303 | localhost | Output suppressed because no_log was given 2025-09-27 00:11:10.195321 | 2025-09-27 00:11:10.195464 | TASK [Set zuul-log-path fact] 2025-09-27 00:11:10.221349 | localhost | skipping: Conditional result was False 2025-09-27 00:11:10.228412 | 2025-09-27 00:11:10.228551 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-09-27 00:11:10.673335 | localhost -> localhost | ok: Runtime: 0:00:00.008186 2025-09-27 00:11:10.682272 | 2025-09-27 00:11:10.682413 | TASK [upload-logs-swift : Upload logs to swift]