2025-09-24 00:17:04.171124 | Job console starting... 2025-09-24 00:17:04.188012 | Updating repositories 2025-09-24 00:17:04.761724 | Preparing job workspace 2025-09-24 00:17:08.378184 | Running Ansible setup... 2025-09-24 00:17:14.237015 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-24 00:17:14.929303 | 2025-09-24 00:17:14.929461 | PLAY [localhost] 2025-09-24 00:17:14.945215 | 2025-09-24 00:17:14.945368 | TASK [Gathering Facts] 2025-09-24 00:17:16.022619 | localhost | ok 2025-09-24 00:17:16.052415 | 2025-09-24 00:17:16.052591 | TASK [Setup log path fact] 2025-09-24 00:17:16.075986 | localhost | ok 2025-09-24 00:17:16.096006 | 2025-09-24 00:17:16.096143 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-24 00:17:16.126651 | localhost | ok 2025-09-24 00:17:16.134230 | 2025-09-24 00:17:16.134297 | TASK [emit-job-header : Print job information] 2025-09-24 00:17:16.162615 | # Job Information 2025-09-24 00:17:16.162749 | Ansible Version: 2.15.12 2025-09-24 00:17:16.162781 | Job: ansible-test-sanity-docker-milestone 2025-09-24 00:17:16.162803 | Pipeline: periodic 2025-09-24 00:17:16.162822 | Executor: ze04.softwarefactory-project.io 2025-09-24 00:17:16.162841 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-09-24 00:17:16.162863 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/bd3/ansible/bd3aad1c196348209146c1e5bf50eaa2/ 2025-09-24 00:17:16.162883 | Event ID: 3b09a8e0ff9c49ffb90e8d2a452c8a0a 2025-09-24 00:17:16.166638 | 2025-09-24 00:17:16.166719 | LOOP [emit-job-header : Print node information] 2025-09-24 00:17:16.261393 | localhost | ok: 2025-09-24 00:17:16.261637 | localhost | # Node Information 2025-09-24 00:17:16.261693 | localhost | Inventory Hostname: controller 2025-09-24 00:17:16.261727 | localhost | Hostname: ip-172-16-213-84 2025-09-24 00:17:16.261754 | localhost | Username: zuul-worker 2025-09-24 00:17:16.261781 | localhost | Distro: Fedora 37 2025-09-24 00:17:16.261806 | localhost | Provider: ansible-us-east-2 2025-09-24 00:17:16.261830 | localhost | Region: us-east-2 2025-09-24 00:17:16.261851 | localhost | Label: ansible-fedora-37-1vcpu 2025-09-24 00:17:16.261874 | localhost | Product Name: t3.small 2025-09-24 00:17:16.261897 | localhost | Interface IP: 3.19.229.78 2025-09-24 00:17:16.280099 | 2025-09-24 00:17:16.280216 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-24 00:17:16.733384 | localhost -> localhost | changed 2025-09-24 00:17:16.739661 | 2025-09-24 00:17:16.739771 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-24 00:17:17.733674 | localhost -> localhost | changed 2025-09-24 00:17:17.775819 | 2025-09-24 00:17:17.776064 | PLAY [all:!appliance*] 2025-09-24 00:17:17.799976 | 2025-09-24 00:17:17.800144 | TASK [include_role : start-zuul-console] 2025-09-24 00:17:17.824745 | controller | ok 2025-09-24 00:17:17.845209 | 2025-09-24 00:17:17.845374 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-24 00:17:18.512937 | controller | ok 2025-09-24 00:17:18.524246 | 2025-09-24 00:17:18.524318 | TASK [use-our-mirror : Retrieve the IP address] 2025-09-24 00:17:23.118973 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-09-24 00:17:23.127813 | 2025-09-24 00:17:23.127908 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-09-24 00:17:23.278591 | controller | skipping: Conditional result was False 2025-09-24 00:17:23.290072 | 2025-09-24 00:17:23.290220 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-09-24 00:17:23.317192 | controller | skipping: Conditional result was False 2025-09-24 00:17:23.327646 | 2025-09-24 00:17:23.327863 | TASK [use-our-mirror : Create the podman configuration directory] 2025-09-24 00:17:23.354821 | controller | skipping: Conditional result was False 2025-09-24 00:17:23.365793 | 2025-09-24 00:17:23.365920 | TASK [use-our-mirror : Copy the podman configuration] 2025-09-24 00:17:23.392110 | controller | skipping: Conditional result was False 2025-09-24 00:17:23.400980 | 2025-09-24 00:17:23.401077 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-09-24 00:17:23.427141 | controller | skipping: Conditional result was False 2025-09-24 00:17:23.441528 | 2025-09-24 00:17:23.441651 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-09-24 00:17:23.469914 | controller | skipping: Conditional result was False 2025-09-24 00:17:23.486094 | 2025-09-24 00:17:23.486188 | TASK [Disable Fedora Modular] 2025-09-24 00:17:24.361610 | controller | changed 2025-09-24 00:17:24.370001 | 2025-09-24 00:17:24.370125 | TASK [Enable EPEL] 2025-09-24 00:17:24.396546 | controller | skipping: Conditional result was False 2025-09-24 00:17:24.404562 | 2025-09-24 00:17:24.404653 | TASK [Register the RHEL node] 2025-09-24 00:17:24.582969 | 2025-09-24 00:17:24.583156 | TASK [Show the subscription-manager status] 2025-09-24 00:17:24.722049 | controller | skipping: Conditional result was False 2025-09-24 00:17:24.735773 | 2025-09-24 00:17:24.735921 | TASK [Enable EPEL on RHEL] 2025-09-24 00:17:24.901299 | controller | skipping: Conditional result was False 2025-09-24 00:17:24.910352 | 2025-09-24 00:17:24.910467 | TASK [Install git and tox] 2025-09-24 00:18:57.436786 | controller | changed 2025-09-24 00:18:57.443378 | 2025-09-24 00:18:57.443449 | TASK [include_role : prepare-workspace] 2025-09-24 00:18:57.485416 | controller | ok 2025-09-24 00:18:57.506277 | 2025-09-24 00:18:57.506397 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-24 00:18:58.086582 | controller | ok 2025-09-24 00:18:58.100014 | 2025-09-24 00:18:58.100148 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-24 00:19:11.617062 | controller | Output suppressed because no_log was given 2025-09-24 00:19:11.678568 | 2025-09-24 00:19:11.678716 | TASK [include_role : prepare-workspace-openshift] 2025-09-24 00:19:11.703443 | controller | skipping: Conditional result was False 2025-09-24 00:19:11.725131 | 2025-09-24 00:19:11.725196 | PLAY [all:!appliance] 2025-09-24 00:19:11.742515 | 2025-09-24 00:19:11.742593 | TASK [Run add-build-sshkey role (RSA)] 2025-09-24 00:19:11.775697 | controller | ok 2025-09-24 00:19:11.796373 | 2025-09-24 00:19:11.796476 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-24 00:19:12.127902 | controller -> localhost | ok 2025-09-24 00:19:12.150456 | 2025-09-24 00:19:12.150757 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-24 00:19:12.180445 | controller | ok 2025-09-24 00:19:12.204968 | controller | included: /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-24 00:19:12.214078 | 2025-09-24 00:19:12.214360 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-24 00:19:12.791212 | controller -> localhost | Generating public/private rsa key pair. 2025-09-24 00:19:12.791578 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/work/bd3aad1c196348209146c1e5bf50eaa2_id_rsa. 2025-09-24 00:19:12.791648 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/work/bd3aad1c196348209146c1e5bf50eaa2_id_rsa.pub. 2025-09-24 00:19:12.791751 | controller -> localhost | The key fingerprint is: 2025-09-24 00:19:12.791807 | controller -> localhost | SHA256:CqAidjgEucyAjUjXi/knp5pSquO9I4LsxPfWmTncODs zuul-build-sshkey 2025-09-24 00:19:12.791853 | controller -> localhost | The key's randomart image is: 2025-09-24 00:19:12.791897 | controller -> localhost | +---[RSA 2048]----+ 2025-09-24 00:19:12.791940 | controller -> localhost | |== .. | 2025-09-24 00:19:12.791984 | controller -> localhost | |B o . | 2025-09-24 00:19:12.792025 | controller -> localhost | |+o. o . | 2025-09-24 00:19:12.792066 | controller -> localhost | |o+.+ . | 2025-09-24 00:19:12.792107 | controller -> localhost | |++ .o S | 2025-09-24 00:19:12.792172 | controller -> localhost | |= o. + + | 2025-09-24 00:19:12.792230 | controller -> localhost | |ooo. O * | 2025-09-24 00:19:12.792278 | controller -> localhost | |==o.oo E . | 2025-09-24 00:19:12.792323 | controller -> localhost | |*+o==. .= | 2025-09-24 00:19:12.792373 | controller -> localhost | +----[SHA256]-----+ 2025-09-24 00:19:12.792479 | controller -> localhost | ok: Runtime: 0:00:00.206921 2025-09-24 00:19:12.807610 | 2025-09-24 00:19:12.807816 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-24 00:19:12.850153 | controller | ok 2025-09-24 00:19:12.865205 | controller | included: /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-24 00:19:12.878005 | 2025-09-24 00:19:12.878138 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-24 00:19:12.904592 | controller | skipping: Conditional result was False 2025-09-24 00:19:12.914525 | 2025-09-24 00:19:12.914710 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-24 00:19:13.581090 | controller | changed 2025-09-24 00:19:13.587701 | 2025-09-24 00:19:13.587791 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-24 00:19:13.934102 | controller | ok 2025-09-24 00:19:13.947785 | 2025-09-24 00:19:13.947921 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-24 00:19:15.191375 | controller | changed 2025-09-24 00:19:15.199529 | 2025-09-24 00:19:15.199627 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-24 00:19:16.436862 | controller | changed 2025-09-24 00:19:16.445060 | 2025-09-24 00:19:16.445214 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-24 00:19:16.471245 | controller | skipping: Conditional result was False 2025-09-24 00:19:16.483072 | 2025-09-24 00:19:16.483199 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-24 00:19:16.919974 | controller -> localhost | changed 2025-09-24 00:19:16.952043 | 2025-09-24 00:19:16.952232 | TASK [add-build-sshkey : Add back temp key] 2025-09-24 00:19:17.288979 | controller -> localhost | Identity added: /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/work/bd3aad1c196348209146c1e5bf50eaa2_id_rsa (zuul-build-sshkey) 2025-09-24 00:19:17.289606 | controller -> localhost | ok: Runtime: 0:00:00.012035 2025-09-24 00:19:17.308197 | 2025-09-24 00:19:17.308450 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-24 00:19:17.814405 | controller | ok 2025-09-24 00:19:17.822023 | 2025-09-24 00:19:17.822122 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-24 00:19:17.858294 | controller | skipping: Conditional result was False 2025-09-24 00:19:17.874303 | 2025-09-24 00:19:17.874413 | TASK [Run add-build-sshkey role (ECDSA)] 2025-09-24 00:19:17.910739 | controller | ok 2025-09-24 00:19:17.936655 | 2025-09-24 00:19:17.936838 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-24 00:19:18.189207 | controller -> localhost | ok 2025-09-24 00:19:18.197734 | 2025-09-24 00:19:18.197881 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-24 00:19:18.229321 | controller | ok 2025-09-24 00:19:18.241912 | controller | included: /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-24 00:19:18.250442 | 2025-09-24 00:19:18.250589 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-24 00:19:18.512573 | controller -> localhost | Generating public/private ecdsa key pair. 2025-09-24 00:19:18.512789 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/work/bd3aad1c196348209146c1e5bf50eaa2_id_ecdsa. 2025-09-24 00:19:18.512836 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/work/bd3aad1c196348209146c1e5bf50eaa2_id_ecdsa.pub. 2025-09-24 00:19:18.512870 | controller -> localhost | The key fingerprint is: 2025-09-24 00:19:18.512892 | controller -> localhost | SHA256:zErGqWv+vt/UNuDYKDx7h83hmqwqT/Gt+GfSj2eY85A zuul-build-sshkey 2025-09-24 00:19:18.512912 | controller -> localhost | The key's randomart image is: 2025-09-24 00:19:18.512931 | controller -> localhost | +---[ECDSA 521]---+ 2025-09-24 00:19:18.512949 | controller -> localhost | | | 2025-09-24 00:19:18.512967 | controller -> localhost | | | 2025-09-24 00:19:18.512985 | controller -> localhost | | | 2025-09-24 00:19:18.513003 | controller -> localhost | | . + | 2025-09-24 00:19:18.513020 | controller -> localhost | | . = S . | 2025-09-24 00:19:18.513039 | controller -> localhost | | B o *.o | 2025-09-24 00:19:18.513056 | controller -> localhost | | o *.EB+.+ | 2025-09-24 00:19:18.513073 | controller -> localhost | | ...o.*X*B. . | 2025-09-24 00:19:18.513092 | controller -> localhost | | =*=OO*O+ | 2025-09-24 00:19:18.513115 | controller -> localhost | +----[SHA256]-----+ 2025-09-24 00:19:18.513165 | controller -> localhost | ok: Runtime: 0:00:00.007783 2025-09-24 00:19:18.519756 | 2025-09-24 00:19:18.519829 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-24 00:19:18.540637 | controller | ok 2025-09-24 00:19:18.548088 | controller | included: /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-24 00:19:18.557090 | 2025-09-24 00:19:18.557167 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-24 00:19:18.571615 | controller | skipping: Conditional result was False 2025-09-24 00:19:18.578518 | 2025-09-24 00:19:18.578606 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-24 00:19:19.014521 | controller | changed 2025-09-24 00:19:19.028976 | 2025-09-24 00:19:19.029139 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-24 00:19:19.386900 | controller | ok 2025-09-24 00:19:19.401881 | 2025-09-24 00:19:19.402031 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-24 00:19:20.621581 | controller | changed 2025-09-24 00:19:20.637576 | 2025-09-24 00:19:20.637811 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-24 00:19:21.955328 | controller | changed 2025-09-24 00:19:21.965214 | 2025-09-24 00:19:21.965417 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-24 00:19:21.994665 | controller | skipping: Conditional result was False 2025-09-24 00:19:22.005124 | 2025-09-24 00:19:22.005264 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-24 00:19:22.291992 | controller -> localhost | changed 2025-09-24 00:19:22.372535 | 2025-09-24 00:19:22.372732 | TASK [add-build-sshkey : Add back temp key] 2025-09-24 00:19:22.706772 | controller -> localhost | Identity added: /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/work/bd3aad1c196348209146c1e5bf50eaa2_id_ecdsa (zuul-build-sshkey) 2025-09-24 00:19:22.707441 | controller -> localhost | ok: Runtime: 0:00:00.015070 2025-09-24 00:19:22.714161 | 2025-09-24 00:19:22.714234 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-24 00:19:23.070340 | controller | ok 2025-09-24 00:19:23.078994 | 2025-09-24 00:19:23.079117 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-24 00:19:23.118432 | controller | skipping: Conditional result was False 2025-09-24 00:19:23.136311 | 2025-09-24 00:19:23.136477 | TASK [include_role : remove-zuul-sshkey] 2025-09-24 00:19:23.163973 | controller | skipping: Conditional result was False 2025-09-24 00:19:23.172454 | 2025-09-24 00:19:23.172550 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-24 00:19:23.542973 | controller | ok: "logs" 2025-09-24 00:19:23.543544 | controller | ok: All items complete 2025-09-24 00:19:23.543633 | 2025-09-24 00:19:23.833671 | controller | ok: "artifacts" 2025-09-24 00:19:24.130911 | controller | ok: "docs" 2025-09-24 00:19:24.148782 | 2025-09-24 00:19:24.148938 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-24 00:19:24.472340 | controller | changed: "logs" 2025-09-24 00:19:24.760810 | controller | changed: "artifacts" 2025-09-24 00:19:25.060182 | controller | changed: "docs" 2025-09-24 00:19:25.132225 | 2025-09-24 00:19:25.132403 | PLAY RECAP 2025-09-24 00:19:25.132491 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-09-24 00:19:25.132547 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-24 00:19:25.132587 | 2025-09-24 00:19:25.264671 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-24 00:19:25.265528 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-24 00:19:25.878588 | 2025-09-24 00:19:25.878731 | PLAY [all] 2025-09-24 00:19:25.902208 | 2025-09-24 00:19:25.902326 | TASK [Install binary dependencies] 2025-09-24 00:19:25.983561 | controller | ok 2025-09-24 00:19:26.003178 | 2025-09-24 00:19:26.003291 | TASK [bindep : Include find tasks] 2025-09-24 00:19:26.035206 | controller | ok 2025-09-24 00:19:26.046488 | controller | included: /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-24 00:19:26.056209 | 2025-09-24 00:19:26.056310 | TASK [bindep : Look for bindep.txt] 2025-09-24 00:19:26.578815 | controller | ok 2025-09-24 00:19:26.586841 | 2025-09-24 00:19:26.586974 | TASK [bindep : Define bindep_file fact] 2025-09-24 00:19:26.612389 | controller | skipping: Conditional result was False 2025-09-24 00:19:26.621753 | 2025-09-24 00:19:26.621874 | TASK [bindep : Look for other-requirements.txt] 2025-09-24 00:19:26.918905 | controller | ok 2025-09-24 00:19:26.924852 | 2025-09-24 00:19:26.924926 | TASK [bindep : Define bindep_file fact] 2025-09-24 00:19:26.960901 | controller | skipping: Conditional result was False 2025-09-24 00:19:26.968130 | 2025-09-24 00:19:26.968229 | TASK [bindep : Look for bindep fallback file] 2025-09-24 00:19:27.002942 | controller | skipping: Conditional result was False 2025-09-24 00:19:27.010860 | 2025-09-24 00:19:27.010959 | TASK [bindep : Define bindep_file fact] 2025-09-24 00:19:27.036977 | controller | skipping: Conditional result was False 2025-09-24 00:19:27.051155 | 2025-09-24 00:19:27.051303 | TASK [bindep : Include bindep tasks] 2025-09-24 00:19:27.088219 | controller | skipping: Conditional result was False 2025-09-24 00:19:27.100102 | 2025-09-24 00:19:27.100276 | TASK [bindep : Include install tasks] 2025-09-24 00:19:27.126046 | controller | skipping: Conditional result was False 2025-09-24 00:19:27.136811 | 2025-09-24 00:19:27.136953 | LOOP [bindep : Include package tasks] 2025-09-24 00:19:27.213294 | 2025-09-24 00:19:27.213608 | TASK [Run test-setup role] 2025-09-24 00:19:27.237985 | controller | ok 2025-09-24 00:19:27.269792 | 2025-09-24 00:19:27.269928 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-24 00:19:27.561430 | controller | ok 2025-09-24 00:19:27.574642 | 2025-09-24 00:19:27.574857 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-24 00:19:27.725874 | controller | skipping: Conditional result was False 2025-09-24 00:19:27.769100 | 2025-09-24 00:19:27.769237 | PLAY RECAP 2025-09-24 00:19:27.769313 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-24 00:19:27.769356 | 2025-09-24 00:19:27.910304 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-24 00:19:27.911311 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-24 00:19:28.576217 | 2025-09-24 00:19:28.576362 | PLAY [controller] 2025-09-24 00:19:28.597951 | 2025-09-24 00:19:28.598081 | TASK [Create the /root directory] 2025-09-24 00:19:29.352315 | controller | ok 2025-09-24 00:19:29.359124 | 2025-09-24 00:19:29.359243 | TASK [Install glibc-langpack-en] 2025-09-24 00:19:37.606039 | controller | ok: Nothing to do 2025-09-24 00:19:37.619836 | 2025-09-24 00:19:37.620056 | TASK [Ensure controller directory exists] 2025-09-24 00:19:38.030219 | controller | changed 2025-09-24 00:19:38.044126 | 2025-09-24 00:19:38.044321 | TASK [Install container runtime] 2025-09-24 00:19:38.111229 | controller | ok 2025-09-24 00:19:38.175127 | 2025-09-24 00:19:38.175253 | LOOP [ensure-podman : Find distribution installation] 2025-09-24 00:19:38.209178 | controller | ok: "/var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-09-24 00:19:38.224105 | controller | included: /var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-09-24 00:19:38.232902 | 2025-09-24 00:19:38.233059 | TASK [ensure-podman : Install podman (RedHat)] 2025-09-24 00:20:56.931597 | controller | changed 2025-09-24 00:20:56.940514 | 2025-09-24 00:20:56.940769 | TASK [ensure-podman : Fetch podman version] 2025-09-24 00:20:57.715690 | controller | Client: Podman Engine 2025-09-24 00:20:57.715786 | controller | Version: 4.6.2 2025-09-24 00:20:57.715816 | controller | API Version: 4.6.2 2025-09-24 00:20:57.716311 | controller | Go Version: go1.19.12 2025-09-24 00:20:57.716369 | controller | Built: Mon Aug 28 19:38:31 2023 2025-09-24 00:20:57.716404 | controller | OS/Arch: linux/amd64 2025-09-24 00:20:58.085722 | controller | ok: Runtime: 0:00:00.226172 2025-09-24 00:20:58.100872 | 2025-09-24 00:20:58.101040 | TASK [ensure-podman : Print podman version installed] 2025-09-24 00:20:58.143034 | Podman version: Client: Podman Engine 2025-09-24 00:20:58.143351 | Version: 4.6.2 2025-09-24 00:20:58.143421 | API Version: 4.6.2 2025-09-24 00:20:58.143484 | Go Version: go1.19.12 2025-09-24 00:20:58.143538 | Built: Mon Aug 28 19:38:31 2023 2025-09-24 00:20:58.143599 | OS/Arch: linux/amd64 2025-09-24 00:20:58.157137 | 2025-09-24 00:20:58.157378 | TASK [ensure-podman : Validate podman engine] 2025-09-24 00:20:58.302974 | controller | skipping: Conditional result was False 2025-09-24 00:20:58.315983 | 2025-09-24 00:20:58.316119 | TASK [ensure-podman : Set up docker compatability socket] 2025-09-24 00:20:58.343972 | controller | skipping: Conditional result was False 2025-09-24 00:20:58.367286 | 2025-09-24 00:20:58.367438 | TASK [Ensure python3.8 is present] 2025-09-24 00:20:58.395670 | controller | skipping: Conditional result was False 2025-09-24 00:20:58.411157 | 2025-09-24 00:20:58.411478 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-09-24 00:20:58.438935 | controller | ok 2025-09-24 00:20:58.463613 | 2025-09-24 00:20:58.463730 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-09-24 00:21:02.214283 | controller | ok: Nothing to do 2025-09-24 00:21:02.224298 | 2025-09-24 00:21:02.224403 | TASK [our-ensure-python : Also install python3-devel] 2025-09-24 00:21:15.674343 | controller | changed 2025-09-24 00:21:15.700518 | 2025-09-24 00:21:15.700844 | TASK [Run ensure-virtualenv role] 2025-09-24 00:21:15.733084 | controller | ok 2025-09-24 00:21:15.779099 | 2025-09-24 00:21:15.779289 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-09-24 00:21:16.222960 | controller | /usr/bin/virtualenv 2025-09-24 00:21:16.422650 | controller | ok: Runtime: 0:00:00.004617 2025-09-24 00:21:16.432937 | 2025-09-24 00:21:16.433139 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-09-24 00:21:16.472114 | controller | skipping: Conditional result was False 2025-09-24 00:21:16.472642 | controller | ok: All items complete 2025-09-24 00:21:16.473017 | 2025-09-24 00:21:16.501594 | 2025-09-24 00:21:16.501865 | TASK [Find the full path of the Python interpreter] 2025-09-24 00:21:17.005661 | controller | /usr/bin/python3 2025-09-24 00:21:17.209040 | controller | ok 2025-09-24 00:21:17.217717 | 2025-09-24 00:21:17.217929 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-09-24 00:21:18.663164 | controller | created virtual environment CPython3.11.0.final.0-64 in 795ms 2025-09-24 00:21:18.717374 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-09-24 00:21:18.717433 | 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-24 00:21:18.717450 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-09-24 00:21:18.717472 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-09-24 00:21:18.850257 | controller | changed 2025-09-24 00:21:18.864604 | 2025-09-24 00:21:18.864899 | TASK [Set selinux package] 2025-09-24 00:21:18.916854 | controller | ok 2025-09-24 00:21:18.929845 | 2025-09-24 00:21:18.929991 | TASK [Set selinux package (Fedora)] 2025-09-24 00:21:18.975330 | controller | ok 2025-09-24 00:21:18.985303 | 2025-09-24 00:21:18.985453 | TASK [Install selinux into virtualenv] 2025-09-24 00:21:21.603650 | controller | Collecting selinux-please-lie-to-me 2025-09-24 00:21:21.706351 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-09-24 00:21:22.232112 | controller | Collecting setuptools<50.0.0 2025-09-24 00:21:22.247202 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-09-24 00:21:22.369707 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00 2025-09-24 00:21:22.528389 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-09-24 00:21:22.528797 | controller | Attempting uninstall: setuptools 2025-09-24 00:21:22.533668 | controller | Found existing installation: setuptools 62.6.0 2025-09-24 00:21:22.647244 | controller | Uninstalling setuptools-62.6.0: 2025-09-24 00:21:22.662039 | controller | Successfully uninstalled setuptools-62.6.0 2025-09-24 00:21:23.449705 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-09-24 00:21:23.663965 | controller | 2025-09-24 00:21:23.878437 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-24 00:21:23.878488 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-24 00:21:24.129068 | controller | ok: Runtime: 0:00:04.427027 2025-09-24 00:21:24.146944 | 2025-09-24 00:21:24.147189 | TASK [Install pytest-forked into virtualenv] 2025-09-24 00:21:25.369243 | controller | Collecting pytest-forked 2025-09-24 00:21:25.457671 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-09-24 00:21:25.517336 | controller | Collecting py 2025-09-24 00:21:25.530382 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-09-24 00:21:25.567121 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00 2025-09-24 00:21:25.745143 | controller | Collecting pytest>=3.10 2025-09-24 00:21:25.757378 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-09-24 00:21:25.819468 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.1 MB/s eta 0:00:00 2025-09-24 00:21:25.876501 | controller | Collecting iniconfig>=1 2025-09-24 00:21:25.888822 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-09-24 00:21:25.954709 | controller | Collecting packaging>=20 2025-09-24 00:21:25.967024 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-09-24 00:21:25.979254 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.7 MB/s eta 0:00:00 2025-09-24 00:21:26.026625 | controller | Collecting pluggy<2,>=1.5 2025-09-24 00:21:26.039224 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-09-24 00:21:26.121541 | controller | Collecting pygments>=2.7.2 2025-09-24 00:21:26.133667 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-09-24 00:21:26.250841 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.7 MB/s eta 0:00:00 2025-09-24 00:21:26.383452 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-09-24 00:21:28.656530 | 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-24 00:21:28.682050 | controller | 2025-09-24 00:21:28.883544 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-24 00:21:28.883598 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-24 00:21:29.322798 | controller | ok: Runtime: 0:00:04.257897 2025-09-24 00:21:29.328585 | 2025-09-24 00:21:29.328652 | TASK [Update pip] 2025-09-24 00:21:30.374298 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-09-24 00:21:30.660215 | controller | Collecting pip 2025-09-24 00:21:30.753181 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-09-24 00:21:30.915530 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.1 MB/s eta 0:00:00 2025-09-24 00:21:31.079927 | controller | Installing collected packages: pip 2025-09-24 00:21:31.080886 | controller | Attempting uninstall: pip 2025-09-24 00:21:31.085521 | controller | Found existing installation: pip 22.2.2 2025-09-24 00:21:31.349046 | controller | Uninstalling pip-22.2.2: 2025-09-24 00:21:31.379091 | controller | Successfully uninstalled pip-22.2.2 2025-09-24 00:21:33.012925 | controller | Successfully installed pip-25.2 2025-09-24 00:21:33.480903 | controller | ok: Runtime: 0:00:03.424099 2025-09-24 00:21:33.493903 | 2025-09-24 00:21:33.494089 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-09-24 00:21:33.987232 | controller | changed 2025-09-24 00:21:33.999473 | 2025-09-24 00:21:33.999606 | TASK [Install ansible into virtualenv] 2025-09-24 00:21:35.122013 | controller | Processing ./src/github.com/ansible/ansible 2025-09-24 00:21:35.128233 | controller | Installing build dependencies: started 2025-09-24 00:21:37.019751 | controller | Installing build dependencies: finished with status 'done' 2025-09-24 00:21:38.513060 | controller | Getting requirements to build wheel: started 2025-09-24 00:21:38.513156 | controller | Getting requirements to build wheel: finished with status 'done' 2025-09-24 00:21:39.428143 | controller | Preparing metadata (pyproject.toml): started 2025-09-24 00:21:39.428202 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-09-24 00:21:39.431655 | 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-24 00:21:39.436712 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-09-24 00:21:39.658466 | controller | ERROR 2025-09-24 00:21:39.658889 | controller | { 2025-09-24 00:21:39.658953 | controller | "delta": "0:00:05.156199", 2025-09-24 00:21:39.658996 | controller | "end": "2025-09-24 00:21:39.585229", 2025-09-24 00:21:39.659033 | controller | "msg": "non-zero return code", 2025-09-24 00:21:39.659086 | controller | "rc": 1, 2025-09-24 00:21:39.659124 | controller | "start": "2025-09-24 00:21:34.429030" 2025-09-24 00:21:39.659195 | controller | } failure 2025-09-24 00:21:39.662129 | 2025-09-24 00:21:39.662236 | PLAY RECAP 2025-09-24 00:21:39.662322 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-09-24 00:21:39.662365 | 2025-09-24 00:21:39.862927 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-24 00:21:39.864490 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-24 00:21:40.522666 | 2025-09-24 00:21:40.522823 | PLAY [all] 2025-09-24 00:21:40.548897 | 2025-09-24 00:21:40.549078 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-24 00:21:41.322892 | controller | changed: non-zero return code 2025-09-24 00:21:41.335978 | 2025-09-24 00:21:41.336395 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-24 00:21:41.366200 | controller | skipping: Conditional result was False 2025-09-24 00:21:41.382391 | 2025-09-24 00:21:41.382568 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-24 00:21:41.426597 | 2025-09-24 00:21:41.426973 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-24 00:21:41.463221 | 2025-09-24 00:21:41.463451 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-24 00:21:41.488720 | controller | skipping: Conditional result was False 2025-09-24 00:21:41.499059 | 2025-09-24 00:21:41.499178 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-24 00:21:41.537096 | 2025-09-24 00:21:41.537339 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-24 00:21:41.564785 | controller | skipping: Conditional result was False 2025-09-24 00:21:41.571488 | 2025-09-24 00:21:41.571562 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-24 00:21:41.596598 | controller | skipping: Conditional result was False 2025-09-24 00:21:41.602716 | 2025-09-24 00:21:41.602784 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-24 00:21:41.627450 | controller | skipping: Conditional result was False 2025-09-24 00:21:41.653341 | 2025-09-24 00:21:41.653407 | PLAY RECAP 2025-09-24 00:21:41.653456 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-24 00:21:41.653483 | 2025-09-24 00:21:41.778281 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-24 00:21:41.779316 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-09-24 00:21:42.477597 | 2025-09-24 00:21:42.477806 | PLAY [all:!appliance*] 2025-09-24 00:21:42.499345 | 2025-09-24 00:21:42.499481 | TASK [unregister the node] 2025-09-24 00:21:42.631085 | controller | skipping: Conditional result was False 2025-09-24 00:21:42.643998 | 2025-09-24 00:21:42.644182 | TASK [include_role : fetch-output] 2025-09-24 00:21:42.703070 | controller | ok 2025-09-24 00:21:42.740902 | 2025-09-24 00:21:42.741095 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-24 00:21:42.829370 | controller | skipping: Conditional result was False 2025-09-24 00:21:42.842173 | 2025-09-24 00:21:42.842328 | TASK [fetch-output : Set log path for single node] 2025-09-24 00:21:42.883871 | controller | ok 2025-09-24 00:21:42.896324 | 2025-09-24 00:21:42.896475 | LOOP [fetch-output : Ensure local output dirs] 2025-09-24 00:21:43.342380 | controller -> localhost | ok: "/var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/work/logs" 2025-09-24 00:21:43.601306 | controller -> localhost | changed: "/var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/work/artifacts" 2025-09-24 00:21:43.908136 | controller -> localhost | changed: "/var/lib/zuul/builds/bd3aad1c196348209146c1e5bf50eaa2/work/docs" 2025-09-24 00:21:43.929941 | 2025-09-24 00:21:43.930164 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-24 00:21:45.220298 | controller | changed: 2025-09-24 00:21:45.220823 | controller | .d..t...... ./ 2025-09-24 00:21:45.220928 | controller | cd+++++++++ controller/ 2025-09-24 00:21:45.221046 | controller | changed: All items complete 2025-09-24 00:21:45.221115 | 2025-09-24 00:21:46.347934 | controller | changed: .d..t...... ./ 2025-09-24 00:21:47.443155 | controller | changed: .d..t...... ./ 2025-09-24 00:21:47.464279 | 2025-09-24 00:21:47.464560 | TASK [include_role : fetch-output-openshift] 2025-09-24 00:21:47.490575 | controller | skipping: Conditional result was False 2025-09-24 00:21:47.497723 | 2025-09-24 00:21:47.497797 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-24 00:21:47.527972 | controller | skipping: Conditional result was False 2025-09-24 00:21:47.536010 | controller | skipping: Conditional result was False 2025-09-24 00:21:47.582196 | 2025-09-24 00:21:47.582395 | PLAY [localhost] 2025-09-24 00:21:47.600344 | 2025-09-24 00:21:47.600438 | TASK [Run Zuul manifest role] 2025-09-24 00:21:47.621546 | localhost | ok 2025-09-24 00:21:47.635250 | 2025-09-24 00:21:47.635311 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-24 00:21:48.100607 | localhost | changed 2025-09-24 00:21:48.111660 | 2025-09-24 00:21:48.111928 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-24 00:21:48.162315 | localhost | ok 2025-09-24 00:21:48.180634 | 2025-09-24 00:21:48.180813 | TASK [Set zuul-log-path fact] 2025-09-24 00:21:48.204657 | localhost | ok 2025-09-24 00:21:48.223625 | 2025-09-24 00:21:48.223742 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-24 00:21:48.255993 | localhost | ok 2025-09-24 00:21:48.269334 | 2025-09-24 00:21:48.269422 | LOOP [Run upload-logs-swift role] 2025-09-24 00:21:48.318263 | localhost | Output suppressed because no_log was given 2025-09-24 00:21:48.363670 | 2025-09-24 00:21:48.363833 | TASK [Set zuul-log-path fact] 2025-09-24 00:21:48.400640 | localhost | skipping: Conditional result was False 2025-09-24 00:21:48.408186 | 2025-09-24 00:21:48.408276 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-09-24 00:21:48.986915 | localhost -> localhost | ok: Runtime: 0:00:00.009179 2025-09-24 00:21:48.998714 | 2025-09-24 00:21:48.998872 | TASK [upload-logs-swift : Upload logs to swift]