2025-09-24 00:06:33.121867 | Job console starting... 2025-09-24 00:06:33.131147 | Updating repositories 2025-09-24 00:06:35.179727 | Preparing job workspace 2025-09-24 00:06:39.621717 | Running Ansible setup... 2025-09-24 00:06:46.726650 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-24 00:06:47.354182 | 2025-09-24 00:06:47.354296 | PLAY [localhost] 2025-09-24 00:06:47.362561 | 2025-09-24 00:06:47.362639 | TASK [Gathering Facts] 2025-09-24 00:06:48.448153 | localhost | ok 2025-09-24 00:06:48.464817 | 2025-09-24 00:06:48.464977 | TASK [Setup log path fact] 2025-09-24 00:06:48.485028 | localhost | ok 2025-09-24 00:06:48.503125 | 2025-09-24 00:06:48.503258 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-24 00:06:48.534003 | localhost | ok 2025-09-24 00:06:48.544983 | 2025-09-24 00:06:48.545106 | TASK [emit-job-header : Print job information] 2025-09-24 00:06:48.573439 | # Job Information 2025-09-24 00:06:48.573594 | Ansible Version: 2.15.12 2025-09-24 00:06:48.573627 | Job: ansible-test-sanity-docker-devel 2025-09-24 00:06:48.573649 | Pipeline: periodic 2025-09-24 00:06:48.573668 | Executor: ze04.softwarefactory-project.io 2025-09-24 00:06:48.573707 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-09-24 00:06:48.573731 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/967/ansible/96779f2036b24ef19e23b34691af70dd/ 2025-09-24 00:06:48.573750 | Event ID: 3b09a8e0ff9c49ffb90e8d2a452c8a0a 2025-09-24 00:06:48.577524 | 2025-09-24 00:06:48.577590 | LOOP [emit-job-header : Print node information] 2025-09-24 00:06:48.670806 | localhost | ok: 2025-09-24 00:06:48.670949 | localhost | # Node Information 2025-09-24 00:06:48.670975 | localhost | Inventory Hostname: controller 2025-09-24 00:06:48.670995 | localhost | Hostname: ip-172-16-220-49 2025-09-24 00:06:48.671014 | localhost | Username: zuul-worker 2025-09-24 00:06:48.671034 | localhost | Distro: Fedora 37 2025-09-24 00:06:48.671052 | localhost | Provider: ansible-us-east-2 2025-09-24 00:06:48.671069 | localhost | Region: us-east-2 2025-09-24 00:06:48.671086 | localhost | Label: ansible-fedora-37-1vcpu 2025-09-24 00:06:48.671102 | localhost | Product Name: t3.small 2025-09-24 00:06:48.671118 | localhost | Interface IP: 3.142.143.61 2025-09-24 00:06:48.680368 | 2025-09-24 00:06:48.680482 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-24 00:06:49.089056 | localhost -> localhost | changed 2025-09-24 00:06:49.103263 | 2025-09-24 00:06:49.103339 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-24 00:06:49.979306 | localhost -> localhost | changed 2025-09-24 00:06:50.020841 | 2025-09-24 00:06:50.020939 | PLAY [all:!appliance*] 2025-09-24 00:06:50.053543 | 2025-09-24 00:06:50.053670 | TASK [include_role : start-zuul-console] 2025-09-24 00:06:50.084460 | controller | ok 2025-09-24 00:06:50.103308 | 2025-09-24 00:06:50.103433 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-24 00:06:50.839155 | controller | ok 2025-09-24 00:06:50.850452 | 2025-09-24 00:06:50.863164 | TASK [use-our-mirror : Retrieve the IP address] 2025-09-24 00:06:52.641984 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-09-24 00:06:52.648325 | 2025-09-24 00:06:52.648405 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-09-24 00:06:52.785275 | controller | skipping: Conditional result was False 2025-09-24 00:06:52.797438 | 2025-09-24 00:06:52.797555 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-09-24 00:06:52.817055 | controller | skipping: Conditional result was False 2025-09-24 00:06:52.827082 | 2025-09-24 00:06:52.827193 | TASK [use-our-mirror : Create the podman configuration directory] 2025-09-24 00:06:52.861769 | controller | skipping: Conditional result was False 2025-09-24 00:06:52.869874 | 2025-09-24 00:06:52.869963 | TASK [use-our-mirror : Copy the podman configuration] 2025-09-24 00:06:52.885003 | controller | skipping: Conditional result was False 2025-09-24 00:06:52.893834 | 2025-09-24 00:06:52.893930 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-09-24 00:06:52.918887 | controller | skipping: Conditional result was False 2025-09-24 00:06:52.926788 | 2025-09-24 00:06:52.926885 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-09-24 00:06:52.952590 | controller | skipping: Conditional result was False 2025-09-24 00:06:52.964853 | 2025-09-24 00:06:52.964936 | TASK [Disable Fedora Modular] 2025-09-24 00:06:53.658255 | controller | changed 2025-09-24 00:06:53.669673 | 2025-09-24 00:06:53.669833 | TASK [Enable EPEL] 2025-09-24 00:06:53.698919 | controller | skipping: Conditional result was False 2025-09-24 00:06:53.714641 | 2025-09-24 00:06:53.714802 | TASK [Register the RHEL node] 2025-09-24 00:06:53.865183 | 2025-09-24 00:06:53.865367 | TASK [Show the subscription-manager status] 2025-09-24 00:06:54.037834 | controller | skipping: Conditional result was False 2025-09-24 00:06:54.044657 | 2025-09-24 00:06:54.044756 | TASK [Enable EPEL on RHEL] 2025-09-24 00:06:54.188366 | controller | skipping: Conditional result was False 2025-09-24 00:06:54.202533 | 2025-09-24 00:06:54.202750 | TASK [Install git and tox] 2025-09-24 00:08:21.571828 | controller | changed 2025-09-24 00:08:21.580305 | 2025-09-24 00:08:21.580419 | TASK [include_role : prepare-workspace] 2025-09-24 00:08:21.613503 | controller | ok 2025-09-24 00:08:21.642319 | 2025-09-24 00:08:21.642472 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-24 00:08:22.152764 | controller | ok 2025-09-24 00:08:22.163243 | 2025-09-24 00:08:22.163356 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-24 00:08:36.343926 | controller | Output suppressed because no_log was given 2025-09-24 00:08:36.358837 | 2025-09-24 00:08:36.358926 | TASK [include_role : prepare-workspace-openshift] 2025-09-24 00:08:36.388564 | controller | skipping: Conditional result was False 2025-09-24 00:08:36.429534 | 2025-09-24 00:08:36.429638 | PLAY [all:!appliance] 2025-09-24 00:08:36.529744 | 2025-09-24 00:08:36.529940 | TASK [Run add-build-sshkey role (RSA)] 2025-09-24 00:08:36.563528 | controller | ok 2025-09-24 00:08:36.581788 | 2025-09-24 00:08:36.581986 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-24 00:08:36.925800 | controller -> localhost | ok 2025-09-24 00:08:36.932255 | 2025-09-24 00:08:36.932364 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-24 00:08:36.964772 | controller | ok 2025-09-24 00:08:36.988790 | controller | included: /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-24 00:08:36.997196 | 2025-09-24 00:08:36.997341 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-24 00:08:37.523722 | controller -> localhost | Generating public/private rsa key pair. 2025-09-24 00:08:37.523937 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/work/96779f2036b24ef19e23b34691af70dd_id_rsa. 2025-09-24 00:08:37.523980 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/work/96779f2036b24ef19e23b34691af70dd_id_rsa.pub. 2025-09-24 00:08:37.524011 | controller -> localhost | The key fingerprint is: 2025-09-24 00:08:37.524041 | controller -> localhost | SHA256:34Xen3pbcq+HjK0ZdBXDQBSj6A8BXl6x8xkjsdO0VoU zuul-build-sshkey 2025-09-24 00:08:37.524071 | controller -> localhost | The key's randomart image is: 2025-09-24 00:08:37.524099 | controller -> localhost | +---[RSA 2048]----+ 2025-09-24 00:08:37.524125 | controller -> localhost | | . . ++B+=o| 2025-09-24 00:08:37.524152 | controller -> localhost | | . + o B E.o| 2025-09-24 00:08:37.524176 | controller -> localhost | | . + B * .| 2025-09-24 00:08:37.524201 | controller -> localhost | | . . *.+. | 2025-09-24 00:08:37.524226 | controller -> localhost | | So ooo | 2025-09-24 00:08:37.524260 | controller -> localhost | | .o+ + | 2025-09-24 00:08:37.524290 | controller -> localhost | | ..++o.o| 2025-09-24 00:08:37.524316 | controller -> localhost | | .o+==| 2025-09-24 00:08:37.524342 | controller -> localhost | | oo+=+| 2025-09-24 00:08:37.524370 | controller -> localhost | +----[SHA256]-----+ 2025-09-24 00:08:37.524418 | controller -> localhost | ok: Runtime: 0:00:00.114014 2025-09-24 00:08:37.531186 | 2025-09-24 00:08:37.531294 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-24 00:08:37.566869 | controller | ok 2025-09-24 00:08:37.593609 | controller | included: /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-24 00:08:37.619422 | 2025-09-24 00:08:37.619539 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-24 00:08:37.655341 | controller | skipping: Conditional result was False 2025-09-24 00:08:37.664847 | 2025-09-24 00:08:37.664973 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-24 00:08:38.296396 | controller | changed 2025-09-24 00:08:38.304024 | 2025-09-24 00:08:38.304112 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-24 00:08:38.621006 | controller | ok 2025-09-24 00:08:38.634051 | 2025-09-24 00:08:38.634187 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-24 00:08:39.908311 | controller | changed 2025-09-24 00:08:39.921856 | 2025-09-24 00:08:39.921962 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-24 00:08:41.177275 | controller | changed 2025-09-24 00:08:41.185026 | 2025-09-24 00:08:41.185121 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-24 00:08:41.210990 | controller | skipping: Conditional result was False 2025-09-24 00:08:41.220243 | 2025-09-24 00:08:41.220356 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-24 00:08:41.644832 | controller -> localhost | changed 2025-09-24 00:08:41.660307 | 2025-09-24 00:08:41.660504 | TASK [add-build-sshkey : Add back temp key] 2025-09-24 00:08:42.171640 | controller -> localhost | Identity added: /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/work/96779f2036b24ef19e23b34691af70dd_id_rsa (zuul-build-sshkey) 2025-09-24 00:08:42.171888 | controller -> localhost | ok: Runtime: 0:00:00.036679 2025-09-24 00:08:42.179306 | 2025-09-24 00:08:42.179400 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-24 00:08:42.744798 | controller | ok 2025-09-24 00:08:42.763377 | 2025-09-24 00:08:42.763479 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-24 00:08:42.789946 | controller | skipping: Conditional result was False 2025-09-24 00:08:42.801893 | 2025-09-24 00:08:42.801990 | TASK [Run add-build-sshkey role (ECDSA)] 2025-09-24 00:08:42.824224 | controller | ok 2025-09-24 00:08:42.846311 | 2025-09-24 00:08:42.846427 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-24 00:08:43.084248 | controller -> localhost | ok 2025-09-24 00:08:43.099360 | 2025-09-24 00:08:43.099474 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-24 00:08:43.140631 | controller | ok 2025-09-24 00:08:43.164036 | controller | included: /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-24 00:08:43.173959 | 2025-09-24 00:08:43.174045 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-24 00:08:43.557729 | controller -> localhost | Generating public/private ecdsa key pair. 2025-09-24 00:08:43.557945 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/work/96779f2036b24ef19e23b34691af70dd_id_ecdsa. 2025-09-24 00:08:43.557976 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/work/96779f2036b24ef19e23b34691af70dd_id_ecdsa.pub. 2025-09-24 00:08:43.558007 | controller -> localhost | The key fingerprint is: 2025-09-24 00:08:43.558028 | controller -> localhost | SHA256:XT0e84UuYlFOog2FehGvfpe2pWCxwdgxA9xMTCCqfyk zuul-build-sshkey 2025-09-24 00:08:43.558052 | controller -> localhost | The key's randomart image is: 2025-09-24 00:08:43.558078 | controller -> localhost | +---[ECDSA 521]---+ 2025-09-24 00:08:43.558100 | controller -> localhost | | ..=@= o | 2025-09-24 00:08:43.558118 | controller -> localhost | | . .+*+= . . | 2025-09-24 00:08:43.558136 | controller -> localhost | | . ...B o * .| 2025-09-24 00:08:43.558154 | controller -> localhost | | . . .* * o =.| 2025-09-24 00:08:43.558173 | controller -> localhost | | . .S O . o .| 2025-09-24 00:08:43.558191 | controller -> localhost | | . o . = o | 2025-09-24 00:08:43.558209 | controller -> localhost | | E o . = + . | 2025-09-24 00:08:43.558226 | controller -> localhost | | o o + + | 2025-09-24 00:08:43.558244 | controller -> localhost | | o | 2025-09-24 00:08:43.558262 | controller -> localhost | +----[SHA256]-----+ 2025-09-24 00:08:43.558309 | controller -> localhost | ok: Runtime: 0:00:00.019123 2025-09-24 00:08:43.564939 | 2025-09-24 00:08:43.565016 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-24 00:08:43.597806 | controller | ok 2025-09-24 00:08:43.606835 | controller | included: /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-24 00:08:43.616231 | 2025-09-24 00:08:43.616303 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-24 00:08:43.630180 | controller | skipping: Conditional result was False 2025-09-24 00:08:43.637509 | 2025-09-24 00:08:43.637595 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-24 00:08:44.090173 | controller | changed 2025-09-24 00:08:44.109588 | 2025-09-24 00:08:44.109747 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-24 00:08:44.428155 | controller | ok 2025-09-24 00:08:44.433944 | 2025-09-24 00:08:44.434015 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-24 00:08:45.726492 | controller | changed 2025-09-24 00:08:45.735436 | 2025-09-24 00:08:45.735540 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-24 00:08:46.982934 | controller | changed 2025-09-24 00:08:46.995859 | 2025-09-24 00:08:46.996008 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-24 00:08:47.024543 | controller | skipping: Conditional result was False 2025-09-24 00:08:47.046496 | 2025-09-24 00:08:47.046706 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-24 00:08:47.322525 | controller -> localhost | changed 2025-09-24 00:08:47.347521 | 2025-09-24 00:08:47.347763 | TASK [add-build-sshkey : Add back temp key] 2025-09-24 00:08:47.650671 | controller -> localhost | Identity added: /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/work/96779f2036b24ef19e23b34691af70dd_id_ecdsa (zuul-build-sshkey) 2025-09-24 00:08:47.650903 | controller -> localhost | ok: Runtime: 0:00:00.011416 2025-09-24 00:08:47.657848 | 2025-09-24 00:08:47.657938 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-24 00:08:47.993124 | controller | ok 2025-09-24 00:08:47.999134 | 2025-09-24 00:08:47.999250 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-24 00:08:48.033774 | controller | skipping: Conditional result was False 2025-09-24 00:08:48.076996 | 2025-09-24 00:08:48.077103 | TASK [include_role : remove-zuul-sshkey] 2025-09-24 00:08:48.100951 | controller | skipping: Conditional result was False 2025-09-24 00:08:48.107363 | 2025-09-24 00:08:48.107456 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-24 00:08:48.416929 | controller | ok: "logs" 2025-09-24 00:08:48.417305 | controller | ok: All items complete 2025-09-24 00:08:48.417336 | 2025-09-24 00:08:48.678736 | controller | ok: "artifacts" 2025-09-24 00:08:48.947194 | controller | ok: "docs" 2025-09-24 00:08:48.964708 | 2025-09-24 00:08:48.964872 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-24 00:08:49.272332 | controller | changed: "logs" 2025-09-24 00:08:49.541757 | controller | changed: "artifacts" 2025-09-24 00:08:49.811995 | controller | changed: "docs" 2025-09-24 00:08:49.845784 | 2025-09-24 00:08:49.845885 | PLAY RECAP 2025-09-24 00:08:49.845944 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-09-24 00:08:49.845974 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-24 00:08:49.845994 | 2025-09-24 00:08:49.975026 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-24 00:08:49.975979 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-24 00:08:50.624200 | 2025-09-24 00:08:50.624342 | PLAY [all] 2025-09-24 00:08:50.648136 | 2025-09-24 00:08:50.648309 | TASK [Install binary dependencies] 2025-09-24 00:08:50.711184 | controller | ok 2025-09-24 00:08:50.742719 | 2025-09-24 00:08:50.742888 | TASK [bindep : Include find tasks] 2025-09-24 00:08:50.809852 | controller | ok 2025-09-24 00:08:50.819202 | controller | included: /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-24 00:08:50.826427 | 2025-09-24 00:08:50.826527 | TASK [bindep : Look for bindep.txt] 2025-09-24 00:08:51.362022 | controller | ok 2025-09-24 00:08:51.370371 | 2025-09-24 00:08:51.370480 | TASK [bindep : Define bindep_file fact] 2025-09-24 00:08:51.384607 | controller | skipping: Conditional result was False 2025-09-24 00:08:51.394714 | 2025-09-24 00:08:51.394840 | TASK [bindep : Look for other-requirements.txt] 2025-09-24 00:08:51.682423 | controller | ok 2025-09-24 00:08:51.690078 | 2025-09-24 00:08:51.690186 | TASK [bindep : Define bindep_file fact] 2025-09-24 00:08:51.716170 | controller | skipping: Conditional result was False 2025-09-24 00:08:51.726479 | 2025-09-24 00:08:51.726621 | TASK [bindep : Look for bindep fallback file] 2025-09-24 00:08:51.763458 | controller | skipping: Conditional result was False 2025-09-24 00:08:51.774157 | 2025-09-24 00:08:51.774293 | TASK [bindep : Define bindep_file fact] 2025-09-24 00:08:51.808021 | controller | skipping: Conditional result was False 2025-09-24 00:08:51.814039 | 2025-09-24 00:08:51.814114 | TASK [bindep : Include bindep tasks] 2025-09-24 00:08:51.837846 | controller | skipping: Conditional result was False 2025-09-24 00:08:51.854104 | 2025-09-24 00:08:51.854222 | TASK [bindep : Include install tasks] 2025-09-24 00:08:51.877989 | controller | skipping: Conditional result was False 2025-09-24 00:08:51.884220 | 2025-09-24 00:08:51.884316 | LOOP [bindep : Include package tasks] 2025-09-24 00:08:51.939095 | 2025-09-24 00:08:51.939249 | TASK [Run test-setup role] 2025-09-24 00:08:51.961095 | controller | ok 2025-09-24 00:08:51.986590 | 2025-09-24 00:08:51.986715 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-24 00:08:52.287912 | controller | ok 2025-09-24 00:08:52.295418 | 2025-09-24 00:08:52.295549 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-24 00:08:52.433751 | controller | skipping: Conditional result was False 2025-09-24 00:08:52.460838 | 2025-09-24 00:08:52.460940 | PLAY RECAP 2025-09-24 00:08:52.460984 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-24 00:08:52.461005 | 2025-09-24 00:08:52.574847 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-24 00:08:52.575733 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-24 00:08:53.164237 | 2025-09-24 00:08:53.164437 | PLAY [controller] 2025-09-24 00:08:53.186378 | 2025-09-24 00:08:53.186494 | TASK [Create the /root directory] 2025-09-24 00:08:53.879838 | controller | ok 2025-09-24 00:08:53.887995 | 2025-09-24 00:08:53.888088 | TASK [Install glibc-langpack-en] 2025-09-24 00:09:01.680607 | controller | ok: Nothing to do 2025-09-24 00:09:01.693014 | 2025-09-24 00:09:01.693178 | TASK [Ensure controller directory exists] 2025-09-24 00:09:02.256588 | controller | changed 2025-09-24 00:09:02.273104 | 2025-09-24 00:09:02.273300 | TASK [Install container runtime] 2025-09-24 00:09:02.354760 | controller | ok 2025-09-24 00:09:02.415160 | 2025-09-24 00:09:02.415322 | LOOP [ensure-podman : Find distribution installation] 2025-09-24 00:09:02.454624 | controller | ok: "/var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-09-24 00:09:02.463986 | controller | included: /var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-09-24 00:09:02.472559 | 2025-09-24 00:09:02.472652 | TASK [ensure-podman : Install podman (RedHat)] 2025-09-24 00:10:15.299109 | controller | changed 2025-09-24 00:10:15.305103 | 2025-09-24 00:10:15.305167 | TASK [ensure-podman : Fetch podman version] 2025-09-24 00:10:16.095495 | controller | Client: Podman Engine 2025-09-24 00:10:16.121263 | controller | Version: 4.6.2 2025-09-24 00:10:16.121321 | controller | API Version: 4.6.2 2025-09-24 00:10:16.121338 | controller | Go Version: go1.19.12 2025-09-24 00:10:16.121376 | controller | Built: Mon Aug 28 19:38:31 2023 2025-09-24 00:10:16.121393 | controller | OS/Arch: linux/amd64 2025-09-24 00:10:16.444006 | controller | ok: Runtime: 0:00:00.231625 2025-09-24 00:10:16.451060 | 2025-09-24 00:10:16.451166 | TASK [ensure-podman : Print podman version installed] 2025-09-24 00:10:16.482144 | Podman version: Client: Podman Engine 2025-09-24 00:10:16.482311 | Version: 4.6.2 2025-09-24 00:10:16.482342 | API Version: 4.6.2 2025-09-24 00:10:16.482363 | Go Version: go1.19.12 2025-09-24 00:10:16.482383 | Built: Mon Aug 28 19:38:31 2023 2025-09-24 00:10:16.482407 | OS/Arch: linux/amd64 2025-09-24 00:10:16.488390 | 2025-09-24 00:10:16.488473 | TASK [ensure-podman : Validate podman engine] 2025-09-24 00:10:16.619538 | controller | skipping: Conditional result was False 2025-09-24 00:10:16.627863 | 2025-09-24 00:10:16.627999 | TASK [ensure-podman : Set up docker compatability socket] 2025-09-24 00:10:16.643073 | controller | skipping: Conditional result was False 2025-09-24 00:10:16.655766 | 2025-09-24 00:10:16.655881 | TASK [Ensure python3.8 is present] 2025-09-24 00:10:16.669884 | controller | skipping: Conditional result was False 2025-09-24 00:10:16.678418 | 2025-09-24 00:10:16.678509 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-09-24 00:10:16.701088 | controller | ok 2025-09-24 00:10:16.730095 | 2025-09-24 00:10:16.730211 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-09-24 00:10:20.456189 | controller | ok: Nothing to do 2025-09-24 00:10:20.471811 | 2025-09-24 00:10:20.472008 | TASK [our-ensure-python : Also install python3-devel] 2025-09-24 00:10:33.434500 | controller | changed 2025-09-24 00:10:33.450520 | 2025-09-24 00:10:33.450658 | TASK [Run ensure-virtualenv role] 2025-09-24 00:10:33.476566 | controller | ok 2025-09-24 00:10:33.508345 | 2025-09-24 00:10:33.508514 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-09-24 00:10:33.868995 | controller | /usr/bin/virtualenv 2025-09-24 00:10:34.144646 | controller | ok: Runtime: 0:00:00.003838 2025-09-24 00:10:34.155075 | 2025-09-24 00:10:34.155229 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-09-24 00:10:34.182936 | controller | skipping: Conditional result was False 2025-09-24 00:10:34.183371 | controller | ok: All items complete 2025-09-24 00:10:34.183410 | 2025-09-24 00:10:34.224668 | 2025-09-24 00:10:34.224855 | TASK [Find the full path of the Python interpreter] 2025-09-24 00:10:34.595496 | controller | /usr/bin/python3 2025-09-24 00:10:34.894103 | controller | ok 2025-09-24 00:10:34.901817 | 2025-09-24 00:10:34.901923 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-09-24 00:10:36.315217 | controller | created virtual environment CPython3.11.0.final.0-64 in 795ms 2025-09-24 00:10:36.359242 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-09-24 00:10:36.359299 | 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:10:36.359315 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-09-24 00:10:36.359338 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-09-24 00:10:36.544980 | controller | changed 2025-09-24 00:10:36.552192 | 2025-09-24 00:10:36.552327 | TASK [Set selinux package] 2025-09-24 00:10:36.573280 | controller | ok 2025-09-24 00:10:36.579249 | 2025-09-24 00:10:36.579346 | TASK [Set selinux package (Fedora)] 2025-09-24 00:10:36.609241 | controller | ok 2025-09-24 00:10:36.614921 | 2025-09-24 00:10:36.615022 | TASK [Install selinux into virtualenv] 2025-09-24 00:10:39.233939 | controller | Collecting selinux-please-lie-to-me 2025-09-24 00:10:39.323389 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-09-24 00:10:39.857541 | controller | Collecting setuptools<50.0.0 2025-09-24 00:10:39.871821 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-09-24 00:10:39.972293 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 8.6 MB/s eta 0:00:00 2025-09-24 00:10:40.123682 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-09-24 00:10:40.123976 | controller | Attempting uninstall: setuptools 2025-09-24 00:10:40.128805 | controller | Found existing installation: setuptools 62.6.0 2025-09-24 00:10:40.241397 | controller | Uninstalling setuptools-62.6.0: 2025-09-24 00:10:40.256114 | controller | Successfully uninstalled setuptools-62.6.0 2025-09-24 00:10:40.984833 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-09-24 00:10:41.190028 | controller | 2025-09-24 00:10:41.385632 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-24 00:10:41.385676 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-24 00:10:41.918118 | controller | ok: Runtime: 0:00:04.314979 2025-09-24 00:10:41.937036 | 2025-09-24 00:10:41.937250 | TASK [Install pytest-forked into virtualenv] 2025-09-24 00:10:43.127675 | controller | Collecting pytest-forked 2025-09-24 00:10:43.220095 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-09-24 00:10:43.295920 | controller | Collecting py 2025-09-24 00:10:43.319626 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-09-24 00:10:43.357550 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00 2025-09-24 00:10:43.537882 | controller | Collecting pytest>=3.10 2025-09-24 00:10:43.554114 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-09-24 00:10:43.615629 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 7.3 MB/s eta 0:00:00 2025-09-24 00:10:43.669579 | controller | Collecting iniconfig>=1 2025-09-24 00:10:43.684383 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-09-24 00:10:43.750149 | controller | Collecting packaging>=20 2025-09-24 00:10:43.764758 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-09-24 00:10:43.777105 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.5 MB/s eta 0:00:00 2025-09-24 00:10:43.823821 | controller | Collecting pluggy<2,>=1.5 2025-09-24 00:10:43.838078 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-09-24 00:10:43.912433 | controller | Collecting pygments>=2.7.2 2025-09-24 00:10:43.926872 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-09-24 00:10:44.085342 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 7.9 MB/s eta 0:00:00 2025-09-24 00:10:44.214648 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-09-24 00:10:46.404655 | 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:10:46.422146 | controller | 2025-09-24 00:10:46.579024 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-24 00:10:46.579067 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-24 00:10:47.115334 | controller | ok: Runtime: 0:00:04.165418 2025-09-24 00:10:47.127583 | 2025-09-24 00:10:47.127745 | TASK [Update pip] 2025-09-24 00:10:48.217785 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-09-24 00:10:48.493691 | controller | Collecting pip 2025-09-24 00:10:48.595016 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-09-24 00:10:48.806542 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.5 MB/s eta 0:00:00 2025-09-24 00:10:48.972268 | controller | Installing collected packages: pip 2025-09-24 00:10:48.972583 | controller | Attempting uninstall: pip 2025-09-24 00:10:48.979540 | controller | Found existing installation: pip 22.2.2 2025-09-24 00:10:49.271112 | controller | Uninstalling pip-22.2.2: 2025-09-24 00:10:49.300595 | controller | Successfully uninstalled pip-22.2.2 2025-09-24 00:10:51.071445 | controller | Successfully installed pip-25.2 2025-09-24 00:10:51.802502 | controller | ok: Runtime: 0:00:03.639638 2025-09-24 00:10:51.817431 | 2025-09-24 00:10:51.817608 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-09-24 00:10:52.332076 | controller | changed 2025-09-24 00:10:52.351951 | 2025-09-24 00:10:52.352059 | TASK [Install ansible into virtualenv] 2025-09-24 00:10:53.517750 | controller | Processing ./src/github.com/ansible/ansible 2025-09-24 00:10:53.526675 | controller | Installing build dependencies: started 2025-09-24 00:10:55.498774 | controller | Installing build dependencies: finished with status 'done' 2025-09-24 00:10:57.060032 | controller | Getting requirements to build wheel: started 2025-09-24 00:10:57.060089 | controller | Getting requirements to build wheel: finished with status 'done' 2025-09-24 00:10:57.063328 | controller | Preparing metadata (pyproject.toml): started 2025-09-24 00:10:57.983302 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-09-24 00:10:57.988097 | 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:10:57.992954 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-09-24 00:10:58.523162 | controller | ERROR 2025-09-24 00:10:58.523438 | controller | { 2025-09-24 00:10:58.523497 | controller | "delta": "0:00:05.320729", 2025-09-24 00:10:58.523539 | controller | "end": "2025-09-24 00:10:58.135744", 2025-09-24 00:10:58.523577 | controller | "msg": "non-zero return code", 2025-09-24 00:10:58.523667 | controller | "rc": 1, 2025-09-24 00:10:58.523858 | controller | "start": "2025-09-24 00:10:52.815015" 2025-09-24 00:10:58.523918 | controller | } failure 2025-09-24 00:10:58.528458 | 2025-09-24 00:10:58.528569 | PLAY RECAP 2025-09-24 00:10:58.528731 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-09-24 00:10:58.528809 | 2025-09-24 00:10:58.675586 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-24 00:10:58.676543 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-24 00:10:59.294598 | 2025-09-24 00:10:59.294738 | PLAY [all] 2025-09-24 00:10:59.318433 | 2025-09-24 00:10:59.318568 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-24 00:11:00.101867 | controller | changed: non-zero return code 2025-09-24 00:11:00.114605 | 2025-09-24 00:11:00.114825 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-24 00:11:00.142610 | controller | skipping: Conditional result was False 2025-09-24 00:11:00.156307 | 2025-09-24 00:11:00.156524 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-24 00:11:00.199326 | 2025-09-24 00:11:00.199628 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-24 00:11:00.241594 | 2025-09-24 00:11:00.241955 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-24 00:11:00.269734 | controller | skipping: Conditional result was False 2025-09-24 00:11:00.279665 | 2025-09-24 00:11:00.279837 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-24 00:11:00.313459 | 2025-09-24 00:11:00.313666 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-24 00:11:00.328771 | controller | skipping: Conditional result was False 2025-09-24 00:11:00.337794 | 2025-09-24 00:11:00.337912 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-24 00:11:00.352800 | controller | skipping: Conditional result was False 2025-09-24 00:11:00.364494 | 2025-09-24 00:11:00.364672 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-24 00:11:00.391146 | controller | skipping: Conditional result was False 2025-09-24 00:11:00.427240 | 2025-09-24 00:11:00.427353 | PLAY RECAP 2025-09-24 00:11:00.427414 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-24 00:11:00.427446 | 2025-09-24 00:11:00.542713 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-24 00:11:00.544140 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-09-24 00:11:01.175651 | 2025-09-24 00:11:01.175799 | PLAY [all:!appliance*] 2025-09-24 00:11:01.199011 | 2025-09-24 00:11:01.199140 | TASK [unregister the node] 2025-09-24 00:11:01.338579 | controller | skipping: Conditional result was False 2025-09-24 00:11:01.345400 | 2025-09-24 00:11:01.345487 | TASK [include_role : fetch-output] 2025-09-24 00:11:01.375294 | controller | ok 2025-09-24 00:11:01.396623 | 2025-09-24 00:11:01.396725 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-24 00:11:01.461428 | controller | skipping: Conditional result was False 2025-09-24 00:11:01.472377 | 2025-09-24 00:11:01.472514 | TASK [fetch-output : Set log path for single node] 2025-09-24 00:11:01.504886 | controller | ok 2025-09-24 00:11:01.511099 | 2025-09-24 00:11:01.511171 | LOOP [fetch-output : Ensure local output dirs] 2025-09-24 00:11:01.903763 | controller -> localhost | ok: "/var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/work/logs" 2025-09-24 00:11:02.162210 | controller -> localhost | changed: "/var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/work/artifacts" 2025-09-24 00:11:02.424029 | controller -> localhost | changed: "/var/lib/zuul/builds/96779f2036b24ef19e23b34691af70dd/work/docs" 2025-09-24 00:11:02.441072 | 2025-09-24 00:11:02.441208 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-24 00:11:03.697890 | controller | changed: 2025-09-24 00:11:03.698211 | controller | .d..t...... ./ 2025-09-24 00:11:03.698273 | controller | cd+++++++++ controller/ 2025-09-24 00:11:03.698345 | controller | changed: All items complete 2025-09-24 00:11:03.698441 | 2025-09-24 00:11:04.798231 | controller | changed: .d..t...... ./ 2025-09-24 00:11:05.863089 | controller | changed: .d..t...... ./ 2025-09-24 00:11:05.887461 | 2025-09-24 00:11:05.887607 | TASK [include_role : fetch-output-openshift] 2025-09-24 00:11:05.913834 | controller | skipping: Conditional result was False 2025-09-24 00:11:05.920959 | 2025-09-24 00:11:05.921085 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-24 00:11:05.969737 | controller | skipping: Conditional result was False 2025-09-24 00:11:05.983125 | controller | skipping: Conditional result was False 2025-09-24 00:11:06.015343 | 2025-09-24 00:11:06.015458 | PLAY [localhost] 2025-09-24 00:11:06.029147 | 2025-09-24 00:11:06.029348 | TASK [Run Zuul manifest role] 2025-09-24 00:11:06.050961 | localhost | ok 2025-09-24 00:11:06.071159 | 2025-09-24 00:11:06.071315 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-24 00:11:06.490300 | localhost | changed 2025-09-24 00:11:06.496242 | 2025-09-24 00:11:06.496336 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-24 00:11:06.536230 | localhost | ok 2025-09-24 00:11:06.545194 | 2025-09-24 00:11:06.545279 | TASK [Set zuul-log-path fact] 2025-09-24 00:11:06.565258 | localhost | ok 2025-09-24 00:11:06.579357 | 2025-09-24 00:11:06.579441 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-24 00:11:06.621796 | localhost | ok 2025-09-24 00:11:06.635343 | 2025-09-24 00:11:06.635470 | LOOP [Run upload-logs-swift role] 2025-09-24 00:11:06.682708 | localhost | Output suppressed because no_log was given 2025-09-24 00:11:06.730055 | 2025-09-24 00:11:06.730172 | TASK [Set zuul-log-path fact] 2025-09-24 00:11:06.765814 | localhost | skipping: Conditional result was False 2025-09-24 00:11:06.773600 | 2025-09-24 00:11:06.773720 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-09-24 00:11:07.220308 | localhost -> localhost | ok: Runtime: 0:00:00.005273 2025-09-24 00:11:07.226235 | 2025-09-24 00:11:07.226328 | TASK [upload-logs-swift : Upload logs to swift]