2025-10-09 00:17:58.553136 | Job console starting... 2025-10-09 00:17:58.563382 | Updating repositories 2025-10-09 00:17:58.667827 | Preparing job workspace 2025-10-09 00:18:02.506797 | Running Ansible setup... 2025-10-09 00:18:09.232407 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-09 00:18:09.861002 | 2025-10-09 00:18:09.861183 | PLAY [localhost] 2025-10-09 00:18:09.870934 | 2025-10-09 00:18:09.871103 | TASK [Gathering Facts] 2025-10-09 00:18:10.872240 | localhost | ok 2025-10-09 00:18:10.890300 | 2025-10-09 00:18:10.890491 | TASK [Setup log path fact] 2025-10-09 00:18:10.908909 | localhost | ok 2025-10-09 00:18:10.922394 | 2025-10-09 00:18:10.922512 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-09 00:18:10.951816 | localhost | ok 2025-10-09 00:18:10.962687 | 2025-10-09 00:18:10.962822 | TASK [emit-job-header : Print job information] 2025-10-09 00:18:10.992908 | # Job Information 2025-10-09 00:18:10.993114 | Ansible Version: 2.15.12 2025-10-09 00:18:10.993150 | Job: ansible-test-sanity-docker-devel 2025-10-09 00:18:10.993175 | Pipeline: periodic 2025-10-09 00:18:10.993197 | Executor: ze01.softwarefactory-project.io 2025-10-09 00:18:10.993218 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-09 00:18:10.993243 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/552/ansible/55282bcdc15c456a8088518c38e79147/ 2025-10-09 00:18:10.993265 | Event ID: 7e5f5b9352a645a081c4b0c8a3c28952 2025-10-09 00:18:10.997531 | 2025-10-09 00:18:10.997644 | LOOP [emit-job-header : Print node information] 2025-10-09 00:18:11.109118 | localhost | ok: 2025-10-09 00:18:11.109390 | localhost | # Node Information 2025-10-09 00:18:11.109431 | localhost | Inventory Hostname: controller 2025-10-09 00:18:11.109456 | localhost | Hostname: ip-172-16-182-245 2025-10-09 00:18:11.109475 | localhost | Username: zuul-worker 2025-10-09 00:18:11.109495 | localhost | Distro: Fedora 37 2025-10-09 00:18:11.109512 | localhost | Provider: ansible-us-east-2 2025-10-09 00:18:11.109529 | localhost | Region: us-east-2 2025-10-09 00:18:11.109547 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-09 00:18:11.109563 | localhost | Product Name: t3.small 2025-10-09 00:18:11.109580 | localhost | Interface IP: 18.218.74.111 2025-10-09 00:18:11.124983 | 2025-10-09 00:18:11.125127 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-09 00:18:11.579825 | localhost -> localhost | changed 2025-10-09 00:18:11.586958 | 2025-10-09 00:18:11.587060 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-09 00:18:12.493966 | localhost -> localhost | changed 2025-10-09 00:18:12.521875 | 2025-10-09 00:18:12.521968 | PLAY [all:!appliance*] 2025-10-09 00:18:12.542809 | 2025-10-09 00:18:12.542950 | TASK [include_role : start-zuul-console] 2025-10-09 00:18:12.564645 | controller | ok 2025-10-09 00:18:12.580320 | 2025-10-09 00:18:12.580435 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-09 00:18:13.267645 | controller | ok 2025-10-09 00:18:13.281879 | 2025-10-09 00:18:13.282037 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-09 00:18:14.765916 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-09 00:18:14.773452 | 2025-10-09 00:18:14.773604 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-09 00:18:14.924052 | controller | skipping: Conditional result was False 2025-10-09 00:18:14.931688 | 2025-10-09 00:18:14.931829 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-09 00:18:14.947769 | controller | skipping: Conditional result was False 2025-10-09 00:18:14.955799 | 2025-10-09 00:18:14.955906 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-09 00:18:14.980746 | controller | skipping: Conditional result was False 2025-10-09 00:18:14.988606 | 2025-10-09 00:18:14.988730 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-09 00:18:15.014445 | controller | skipping: Conditional result was False 2025-10-09 00:18:15.021160 | 2025-10-09 00:18:15.021274 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-09 00:18:15.037464 | controller | skipping: Conditional result was False 2025-10-09 00:18:15.045502 | 2025-10-09 00:18:15.045633 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-09 00:18:15.059871 | controller | skipping: Conditional result was False 2025-10-09 00:18:15.075652 | 2025-10-09 00:18:15.075780 | TASK [Disable Fedora Modular] 2025-10-09 00:18:15.802533 | controller | changed 2025-10-09 00:18:15.808787 | 2025-10-09 00:18:15.808903 | TASK [Enable EPEL] 2025-10-09 00:18:15.834476 | controller | skipping: Conditional result was False 2025-10-09 00:18:15.842037 | 2025-10-09 00:18:15.842161 | TASK [Register the RHEL node] 2025-10-09 00:18:15.995311 | 2025-10-09 00:18:15.995506 | TASK [Show the subscription-manager status] 2025-10-09 00:18:16.144098 | controller | skipping: Conditional result was False 2025-10-09 00:18:16.187730 | 2025-10-09 00:18:16.187860 | TASK [Enable EPEL on RHEL] 2025-10-09 00:18:16.334060 | controller | skipping: Conditional result was False 2025-10-09 00:18:16.343875 | 2025-10-09 00:18:16.344099 | TASK [Install git and tox] 2025-10-09 00:19:55.427497 | controller | changed 2025-10-09 00:19:55.434690 | 2025-10-09 00:19:55.434793 | TASK [include_role : prepare-workspace] 2025-10-09 00:19:55.465980 | controller | ok 2025-10-09 00:19:55.491432 | 2025-10-09 00:19:55.491556 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-09 00:19:56.033951 | controller | ok 2025-10-09 00:19:56.047202 | 2025-10-09 00:19:56.047343 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-09 00:20:09.981447 | controller | Output suppressed because no_log was given 2025-10-09 00:20:10.037489 | 2025-10-09 00:20:10.037740 | TASK [include_role : prepare-workspace-openshift] 2025-10-09 00:20:10.059732 | controller | skipping: Conditional result was False 2025-10-09 00:20:10.085116 | 2025-10-09 00:20:10.085233 | PLAY [all:!appliance] 2025-10-09 00:20:10.108495 | 2025-10-09 00:20:10.108636 | TASK [Run add-build-sshkey role (RSA)] 2025-10-09 00:20:10.130796 | controller | ok 2025-10-09 00:20:10.149467 | 2025-10-09 00:20:10.149607 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-09 00:20:10.398632 | controller -> localhost | ok 2025-10-09 00:20:10.406572 | 2025-10-09 00:20:10.406683 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-09 00:20:10.437846 | controller | ok 2025-10-09 00:20:10.453740 | controller | included: /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-09 00:20:10.460518 | 2025-10-09 00:20:10.460608 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-09 00:20:10.925372 | controller -> localhost | Generating public/private rsa key pair. 2025-10-09 00:20:10.925662 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/work/55282bcdc15c456a8088518c38e79147_id_rsa. 2025-10-09 00:20:10.925703 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/work/55282bcdc15c456a8088518c38e79147_id_rsa.pub. 2025-10-09 00:20:10.925733 | controller -> localhost | The key fingerprint is: 2025-10-09 00:20:10.925757 | controller -> localhost | SHA256:a9MC1qCRWXB2rcuFhJQm1npz+BdtDpDtznh2C16/vwc zuul-build-sshkey 2025-10-09 00:20:10.925779 | controller -> localhost | The key's randomart image is: 2025-10-09 00:20:10.925812 | controller -> localhost | +---[RSA 2048]----+ 2025-10-09 00:20:10.925852 | controller -> localhost | | .+=o.+ | 2025-10-09 00:20:10.925878 | controller -> localhost | | o*=.+ o | 2025-10-09 00:20:10.925904 | controller -> localhost | | .++.o = . | 2025-10-09 00:20:10.925926 | controller -> localhost | | .o+o+ = o | 2025-10-09 00:20:10.925949 | controller -> localhost | | ..o=S* = | 2025-10-09 00:20:10.925986 | controller -> localhost | | . .=oB + E | 2025-10-09 00:20:10.926103 | controller -> localhost | | ==.+ o . | 2025-10-09 00:20:10.926144 | controller -> localhost | | . o. . . .| 2025-10-09 00:20:10.926172 | controller -> localhost | | .++| 2025-10-09 00:20:10.926200 | controller -> localhost | +----[SHA256]-----+ 2025-10-09 00:20:10.926258 | controller -> localhost | ok: Runtime: 0:00:00.074659 2025-10-09 00:20:10.933617 | 2025-10-09 00:20:10.933761 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-09 00:20:10.966330 | controller | ok 2025-10-09 00:20:10.978212 | controller | included: /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-09 00:20:10.990625 | 2025-10-09 00:20:10.990760 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-09 00:20:11.016704 | controller | skipping: Conditional result was False 2025-10-09 00:20:11.023624 | 2025-10-09 00:20:11.023729 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-09 00:20:11.784558 | controller | changed 2025-10-09 00:20:11.792010 | 2025-10-09 00:20:11.792135 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-09 00:20:12.149899 | controller | ok 2025-10-09 00:20:12.157775 | 2025-10-09 00:20:12.157908 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-09 00:20:13.446324 | controller | changed 2025-10-09 00:20:13.452531 | 2025-10-09 00:20:13.452604 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-09 00:20:15.025459 | controller | changed 2025-10-09 00:20:15.032926 | 2025-10-09 00:20:15.033062 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-09 00:20:15.058179 | controller | skipping: Conditional result was False 2025-10-09 00:20:15.065140 | 2025-10-09 00:20:15.065251 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-09 00:20:15.478408 | controller -> localhost | changed 2025-10-09 00:20:15.506862 | 2025-10-09 00:20:15.507130 | TASK [add-build-sshkey : Add back temp key] 2025-10-09 00:20:15.821437 | controller -> localhost | Identity added: /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/work/55282bcdc15c456a8088518c38e79147_id_rsa (zuul-build-sshkey) 2025-10-09 00:20:15.821788 | controller -> localhost | ok: Runtime: 0:00:00.012695 2025-10-09 00:20:15.832085 | 2025-10-09 00:20:15.832254 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-09 00:20:16.386881 | controller | ok 2025-10-09 00:20:16.394196 | 2025-10-09 00:20:16.394293 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-09 00:20:16.420473 | controller | skipping: Conditional result was False 2025-10-09 00:20:16.433374 | 2025-10-09 00:20:16.433497 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-09 00:20:16.455108 | controller | ok 2025-10-09 00:20:16.480231 | 2025-10-09 00:20:16.480370 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-09 00:20:16.730709 | controller -> localhost | ok 2025-10-09 00:20:16.739136 | 2025-10-09 00:20:16.739251 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-09 00:20:16.770557 | controller | ok 2025-10-09 00:20:16.785698 | controller | included: /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-09 00:20:16.792307 | 2025-10-09 00:20:16.792443 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-09 00:20:17.084578 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-09 00:20:17.084799 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/work/55282bcdc15c456a8088518c38e79147_id_ecdsa. 2025-10-09 00:20:17.084830 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/work/55282bcdc15c456a8088518c38e79147_id_ecdsa.pub. 2025-10-09 00:20:17.084869 | controller -> localhost | The key fingerprint is: 2025-10-09 00:20:17.084889 | controller -> localhost | SHA256:tX7o8xAWPkG0G0zQxffC2fk+5xu6o7SoLwyGPG6F/2Q zuul-build-sshkey 2025-10-09 00:20:17.084907 | controller -> localhost | The key's randomart image is: 2025-10-09 00:20:17.084925 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-09 00:20:17.084942 | controller -> localhost | | .++o. | 2025-10-09 00:20:17.084959 | controller -> localhost | | +... . | 2025-10-09 00:20:17.084976 | controller -> localhost | | B o +.| 2025-10-09 00:20:17.084993 | controller -> localhost | | o * +.o| 2025-10-09 00:20:17.085009 | controller -> localhost | | . o S B ..| 2025-10-09 00:20:17.085052 | controller -> localhost | | = + o + .| 2025-10-09 00:20:17.085074 | controller -> localhost | | . = oE +.. o | 2025-10-09 00:20:17.085092 | controller -> localhost | | o .oo .+o....+| 2025-10-09 00:20:17.085110 | controller -> localhost | | . .o+o.=oooo=| 2025-10-09 00:20:17.085129 | controller -> localhost | +----[SHA256]-----+ 2025-10-09 00:20:17.085177 | controller -> localhost | ok: Runtime: 0:00:00.008745 2025-10-09 00:20:17.094543 | 2025-10-09 00:20:17.094693 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-09 00:20:17.126109 | controller | ok 2025-10-09 00:20:17.135767 | controller | included: /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-09 00:20:17.145928 | 2025-10-09 00:20:17.146073 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-09 00:20:17.170504 | controller | skipping: Conditional result was False 2025-10-09 00:20:17.178432 | 2025-10-09 00:20:17.178551 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-09 00:20:17.631102 | controller | changed 2025-10-09 00:20:17.640668 | 2025-10-09 00:20:17.640802 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-09 00:20:17.992099 | controller | ok 2025-10-09 00:20:18.000409 | 2025-10-09 00:20:18.000526 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-09 00:20:19.364728 | controller | changed 2025-10-09 00:20:19.374807 | 2025-10-09 00:20:19.374945 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-09 00:20:20.794905 | controller | changed 2025-10-09 00:20:20.803209 | 2025-10-09 00:20:20.803388 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-09 00:20:20.819472 | controller | skipping: Conditional result was False 2025-10-09 00:20:20.826977 | 2025-10-09 00:20:20.827121 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-09 00:20:21.097931 | controller -> localhost | changed 2025-10-09 00:20:21.169855 | 2025-10-09 00:20:21.170006 | TASK [add-build-sshkey : Add back temp key] 2025-10-09 00:20:21.460428 | controller -> localhost | Identity added: /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/work/55282bcdc15c456a8088518c38e79147_id_ecdsa (zuul-build-sshkey) 2025-10-09 00:20:21.460671 | controller -> localhost | ok: Runtime: 0:00:00.007516 2025-10-09 00:20:21.467477 | 2025-10-09 00:20:21.467618 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-09 00:20:21.876059 | controller | ok 2025-10-09 00:20:21.882908 | 2025-10-09 00:20:21.883011 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-09 00:20:21.907347 | controller | skipping: Conditional result was False 2025-10-09 00:20:21.922436 | 2025-10-09 00:20:21.922554 | TASK [include_role : remove-zuul-sshkey] 2025-10-09 00:20:21.938535 | controller | skipping: Conditional result was False 2025-10-09 00:20:21.945984 | 2025-10-09 00:20:21.946099 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-09 00:20:22.293683 | controller | ok: "logs" 2025-10-09 00:20:22.293960 | controller | ok: All items complete 2025-10-09 00:20:22.293988 | 2025-10-09 00:20:22.640486 | controller | ok: "artifacts" 2025-10-09 00:20:22.946536 | controller | ok: "docs" 2025-10-09 00:20:22.960917 | 2025-10-09 00:20:22.961093 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-09 00:20:23.391220 | controller | changed: "logs" 2025-10-09 00:20:23.769821 | controller | changed: "artifacts" 2025-10-09 00:20:24.217270 | controller | changed: "docs" 2025-10-09 00:20:24.255557 | 2025-10-09 00:20:24.255650 | PLAY RECAP 2025-10-09 00:20:24.255691 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-09 00:20:24.255717 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-09 00:20:24.255735 | 2025-10-09 00:20:24.373579 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-09 00:20:24.375432 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-09 00:20:25.057033 | 2025-10-09 00:20:25.057168 | PLAY [all] 2025-10-09 00:20:25.081537 | 2025-10-09 00:20:25.081692 | TASK [Install binary dependencies] 2025-10-09 00:20:25.135564 | controller | ok 2025-10-09 00:20:25.158530 | 2025-10-09 00:20:25.158683 | TASK [bindep : Include find tasks] 2025-10-09 00:20:25.188105 | controller | ok 2025-10-09 00:20:25.196322 | controller | included: /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-09 00:20:25.202805 | 2025-10-09 00:20:25.202907 | TASK [bindep : Look for bindep.txt] 2025-10-09 00:20:25.754702 | controller | ok 2025-10-09 00:20:25.761218 | 2025-10-09 00:20:25.761331 | TASK [bindep : Define bindep_file fact] 2025-10-09 00:20:25.776238 | controller | skipping: Conditional result was False 2025-10-09 00:20:25.782693 | 2025-10-09 00:20:25.782801 | TASK [bindep : Look for other-requirements.txt] 2025-10-09 00:20:26.128584 | controller | ok 2025-10-09 00:20:26.134724 | 2025-10-09 00:20:26.134836 | TASK [bindep : Define bindep_file fact] 2025-10-09 00:20:26.159215 | controller | skipping: Conditional result was False 2025-10-09 00:20:26.166546 | 2025-10-09 00:20:26.166665 | TASK [bindep : Look for bindep fallback file] 2025-10-09 00:20:26.191984 | controller | skipping: Conditional result was False 2025-10-09 00:20:26.198942 | 2025-10-09 00:20:26.199043 | TASK [bindep : Define bindep_file fact] 2025-10-09 00:20:26.224384 | controller | skipping: Conditional result was False 2025-10-09 00:20:26.231370 | 2025-10-09 00:20:26.231466 | TASK [bindep : Include bindep tasks] 2025-10-09 00:20:26.266367 | controller | skipping: Conditional result was False 2025-10-09 00:20:26.274511 | 2025-10-09 00:20:26.274623 | TASK [bindep : Include install tasks] 2025-10-09 00:20:26.299345 | controller | skipping: Conditional result was False 2025-10-09 00:20:26.309704 | 2025-10-09 00:20:26.309847 | LOOP [bindep : Include package tasks] 2025-10-09 00:20:26.369292 | 2025-10-09 00:20:26.369472 | TASK [Run test-setup role] 2025-10-09 00:20:26.401096 | controller | ok 2025-10-09 00:20:26.420115 | 2025-10-09 00:20:26.420233 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-09 00:20:26.759000 | controller | ok 2025-10-09 00:20:26.767074 | 2025-10-09 00:20:26.767198 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-09 00:20:26.920393 | controller | skipping: Conditional result was False 2025-10-09 00:20:26.946782 | 2025-10-09 00:20:26.946897 | PLAY RECAP 2025-10-09 00:20:26.946942 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-09 00:20:26.946968 | 2025-10-09 00:20:27.067579 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-09 00:20:27.068492 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-09 00:20:27.702180 | 2025-10-09 00:20:27.702398 | PLAY [controller] 2025-10-09 00:20:27.727899 | 2025-10-09 00:20:27.728059 | TASK [Create the /root directory] 2025-10-09 00:20:28.478295 | controller | ok 2025-10-09 00:20:28.489778 | 2025-10-09 00:20:28.490009 | TASK [Install glibc-langpack-en] 2025-10-09 00:20:36.640700 | controller | ok: Nothing to do 2025-10-09 00:20:36.649714 | 2025-10-09 00:20:36.649872 | TASK [Ensure controller directory exists] 2025-10-09 00:20:37.090340 | controller | changed 2025-10-09 00:20:37.103554 | 2025-10-09 00:20:37.103716 | TASK [Install container runtime] 2025-10-09 00:20:37.175097 | controller | ok 2025-10-09 00:20:37.236256 | 2025-10-09 00:20:37.236427 | LOOP [ensure-podman : Find distribution installation] 2025-10-09 00:20:37.278898 | controller | ok: "/var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-09 00:20:37.288174 | controller | included: /var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-09 00:20:37.296049 | 2025-10-09 00:20:37.296153 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-09 00:22:04.651733 | controller | changed 2025-10-09 00:22:04.659157 | 2025-10-09 00:22:04.659240 | TASK [ensure-podman : Fetch podman version] 2025-10-09 00:22:05.468388 | controller | Client: Podman Engine 2025-10-09 00:22:05.504575 | controller | Version: 4.6.2 2025-10-09 00:22:05.504627 | controller | API Version: 4.6.2 2025-10-09 00:22:05.504635 | controller | Go Version: go1.19.12 2025-10-09 00:22:05.504656 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-09 00:22:05.504663 | controller | OS/Arch: linux/amd64 2025-10-09 00:22:05.793388 | controller | ok: Runtime: 0:00:00.283057 2025-10-09 00:22:05.802452 | 2025-10-09 00:22:05.802595 | TASK [ensure-podman : Print podman version installed] 2025-10-09 00:22:05.836478 | Podman version: Client: Podman Engine 2025-10-09 00:22:05.836671 | Version: 4.6.2 2025-10-09 00:22:05.836710 | API Version: 4.6.2 2025-10-09 00:22:05.836739 | Go Version: go1.19.12 2025-10-09 00:22:05.836764 | Built: Mon Aug 28 19:38:31 2023 2025-10-09 00:22:05.836790 | OS/Arch: linux/amd64 2025-10-09 00:22:05.844850 | 2025-10-09 00:22:05.844946 | TASK [ensure-podman : Validate podman engine] 2025-10-09 00:22:05.991920 | controller | skipping: Conditional result was False 2025-10-09 00:22:06.007601 | 2025-10-09 00:22:06.007780 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-09 00:22:06.025797 | controller | skipping: Conditional result was False 2025-10-09 00:22:06.055872 | 2025-10-09 00:22:06.056153 | TASK [Ensure python3.8 is present] 2025-10-09 00:22:06.073590 | controller | skipping: Conditional result was False 2025-10-09 00:22:06.088172 | 2025-10-09 00:22:06.088331 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-09 00:22:06.119195 | controller | ok 2025-10-09 00:22:06.150532 | 2025-10-09 00:22:06.150657 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-09 00:22:09.953016 | controller | ok: Nothing to do 2025-10-09 00:22:09.960771 | 2025-10-09 00:22:09.960863 | TASK [our-ensure-python : Also install python3-devel] 2025-10-09 00:22:24.219062 | controller | changed 2025-10-09 00:22:24.233964 | 2025-10-09 00:22:24.234112 | TASK [Run ensure-virtualenv role] 2025-10-09 00:22:24.267527 | controller | ok 2025-10-09 00:22:24.298440 | 2025-10-09 00:22:24.298563 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-09 00:22:24.706518 | controller | /usr/bin/virtualenv 2025-10-09 00:22:24.936976 | controller | ok: Runtime: 0:00:00.004895 2025-10-09 00:22:24.981051 | 2025-10-09 00:22:24.981221 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-09 00:22:25.023849 | controller | skipping: Conditional result was False 2025-10-09 00:22:25.024195 | controller | ok: All items complete 2025-10-09 00:22:25.024235 | 2025-10-09 00:22:25.041660 | 2025-10-09 00:22:25.041818 | TASK [Find the full path of the Python interpreter] 2025-10-09 00:22:25.576521 | controller | /usr/bin/python3 2025-10-09 00:22:25.756612 | controller | ok 2025-10-09 00:22:25.769079 | 2025-10-09 00:22:25.769230 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-09 00:22:27.226978 | controller | created virtual environment CPython3.11.0.final.0-64 in 748ms 2025-10-09 00:22:27.267855 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-09 00:22:27.267915 | 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-10-09 00:22:27.267932 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-09 00:22:27.267957 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-09 00:22:27.432603 | controller | changed 2025-10-09 00:22:27.448717 | 2025-10-09 00:22:27.449069 | TASK [Set selinux package] 2025-10-09 00:22:27.480735 | controller | ok 2025-10-09 00:22:27.493431 | 2025-10-09 00:22:27.493610 | TASK [Set selinux package (Fedora)] 2025-10-09 00:22:27.539801 | controller | ok 2025-10-09 00:22:27.546198 | 2025-10-09 00:22:27.546323 | TASK [Install selinux into virtualenv] 2025-10-09 00:22:30.055255 | controller | Collecting selinux-please-lie-to-me 2025-10-09 00:22:30.140668 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-09 00:22:30.671340 | controller | Collecting setuptools<50.0.0 2025-10-09 00:22:30.684950 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-09 00:22:30.814392 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.6 MB/s eta 0:00:00 2025-10-09 00:22:30.965693 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-09 00:22:30.966023 | controller | Attempting uninstall: setuptools 2025-10-09 00:22:30.970848 | controller | Found existing installation: setuptools 62.6.0 2025-10-09 00:22:31.085297 | controller | Uninstalling setuptools-62.6.0: 2025-10-09 00:22:31.101480 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-09 00:22:31.814801 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-09 00:22:32.016140 | controller | 2025-10-09 00:22:32.222988 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-09 00:22:32.223037 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-09 00:22:32.729812 | controller | ok: Runtime: 0:00:04.212491 2025-10-09 00:22:32.744403 | 2025-10-09 00:22:32.744591 | TASK [Install pytest-forked into virtualenv] 2025-10-09 00:22:33.938520 | controller | Collecting pytest-forked 2025-10-09 00:22:34.022383 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-09 00:22:34.080361 | controller | Collecting py 2025-10-09 00:22:34.093055 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-09 00:22:34.128163 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00 2025-10-09 00:22:34.303413 | controller | Collecting pytest>=3.10 2025-10-09 00:22:34.316739 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-09 00:22:34.377723 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.2 MB/s eta 0:00:00 2025-10-09 00:22:34.431242 | controller | Collecting iniconfig>=1 2025-10-09 00:22:34.445012 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-09 00:22:34.512434 | controller | Collecting packaging>=20 2025-10-09 00:22:34.525354 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-09 00:22:34.537976 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.5 MB/s eta 0:00:00 2025-10-09 00:22:34.585878 | controller | Collecting pluggy<2,>=1.5 2025-10-09 00:22:34.598571 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-09 00:22:34.673030 | controller | Collecting pygments>=2.7.2 2025-10-09 00:22:34.686044 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-09 00:22:34.810692 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.1 MB/s eta 0:00:00 2025-10-09 00:22:34.941007 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-09 00:22:37.204116 | 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-10-09 00:22:37.220188 | controller | 2025-10-09 00:22:37.403894 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-09 00:22:37.403938 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-09 00:22:37.922256 | controller | ok: Runtime: 0:00:04.168277 2025-10-09 00:22:37.928003 | 2025-10-09 00:22:37.928097 | TASK [Update pip] 2025-10-09 00:22:39.003254 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-09 00:22:39.274568 | controller | Collecting pip 2025-10-09 00:22:39.378454 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-09 00:22:39.543710 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.1 MB/s eta 0:00:00 2025-10-09 00:22:39.717141 | controller | Installing collected packages: pip 2025-10-09 00:22:39.718103 | controller | Attempting uninstall: pip 2025-10-09 00:22:39.723145 | controller | Found existing installation: pip 22.2.2 2025-10-09 00:22:40.007365 | controller | Uninstalling pip-22.2.2: 2025-10-09 00:22:40.036699 | controller | Successfully uninstalled pip-22.2.2 2025-10-09 00:22:41.786753 | controller | Successfully installed pip-25.2 2025-10-09 00:22:42.063729 | controller | ok: Runtime: 0:00:03.580154 2025-10-09 00:22:42.074597 | 2025-10-09 00:22:42.074739 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-09 00:22:42.601786 | controller | changed 2025-10-09 00:22:42.610136 | 2025-10-09 00:22:42.610283 | TASK [Install ansible into virtualenv] 2025-10-09 00:22:43.869431 | controller | Processing ./src/github.com/ansible/ansible 2025-10-09 00:22:43.876097 | controller | Installing build dependencies: started 2025-10-09 00:22:45.879635 | controller | Installing build dependencies: finished with status 'done' 2025-10-09 00:22:45.880557 | controller | Getting requirements to build wheel: started 2025-10-09 00:22:47.408838 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-09 00:22:47.410521 | controller | Preparing metadata (pyproject.toml): started 2025-10-09 00:22:48.330833 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-09 00:22:48.335831 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-10-09 00:22:48.340640 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-09 00:22:48.766896 | controller | ERROR 2025-10-09 00:22:48.767112 | controller | { 2025-10-09 00:22:48.767151 | controller | "delta": "0:00:05.351878", 2025-10-09 00:22:48.767172 | controller | "end": "2025-10-09 00:22:48.490676", 2025-10-09 00:22:48.767189 | controller | "msg": "non-zero return code", 2025-10-09 00:22:48.767225 | controller | "rc": 1, 2025-10-09 00:22:48.767243 | controller | "start": "2025-10-09 00:22:43.138798" 2025-10-09 00:22:48.767258 | controller | } failure 2025-10-09 00:22:48.768824 | 2025-10-09 00:22:48.768870 | PLAY RECAP 2025-10-09 00:22:48.768910 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-09 00:22:48.768942 | 2025-10-09 00:22:48.881630 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-09 00:22:48.883625 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-09 00:22:49.531153 | 2025-10-09 00:22:49.531304 | PLAY [all] 2025-10-09 00:22:49.553291 | 2025-10-09 00:22:49.553396 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-09 00:22:50.342330 | controller | changed: non-zero return code 2025-10-09 00:22:50.350724 | 2025-10-09 00:22:50.350944 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-09 00:22:50.377798 | controller | skipping: Conditional result was False 2025-10-09 00:22:50.386899 | 2025-10-09 00:22:50.387103 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-09 00:22:50.424697 | 2025-10-09 00:22:50.424912 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-09 00:22:50.451217 | 2025-10-09 00:22:50.451390 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-09 00:22:50.466922 | controller | skipping: Conditional result was False 2025-10-09 00:22:50.473411 | 2025-10-09 00:22:50.473490 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-09 00:22:50.496067 | 2025-10-09 00:22:50.496215 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-09 00:22:50.510411 | controller | skipping: Conditional result was False 2025-10-09 00:22:50.516775 | 2025-10-09 00:22:50.516851 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-09 00:22:50.531351 | controller | skipping: Conditional result was False 2025-10-09 00:22:50.538410 | 2025-10-09 00:22:50.538527 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-09 00:22:50.552063 | controller | skipping: Conditional result was False 2025-10-09 00:22:50.579688 | 2025-10-09 00:22:50.579788 | PLAY RECAP 2025-10-09 00:22:50.579831 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-09 00:22:50.579852 | 2025-10-09 00:22:50.685905 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-09 00:22:50.687098 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-09 00:22:51.264784 | 2025-10-09 00:22:51.264998 | PLAY [all:!appliance*] 2025-10-09 00:22:51.287282 | 2025-10-09 00:22:51.287412 | TASK [unregister the node] 2025-10-09 00:22:51.427985 | controller | skipping: Conditional result was False 2025-10-09 00:22:51.437082 | 2025-10-09 00:22:51.437270 | TASK [include_role : fetch-output] 2025-10-09 00:22:51.495548 | controller | ok 2025-10-09 00:22:51.534667 | 2025-10-09 00:22:51.534811 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-09 00:22:51.613735 | controller | skipping: Conditional result was False 2025-10-09 00:22:51.626652 | 2025-10-09 00:22:51.626829 | TASK [fetch-output : Set log path for single node] 2025-10-09 00:22:51.676806 | controller | ok 2025-10-09 00:22:51.688957 | 2025-10-09 00:22:51.689143 | LOOP [fetch-output : Ensure local output dirs] 2025-10-09 00:22:52.202551 | controller -> localhost | ok: "/var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/work/logs" 2025-10-09 00:22:52.453402 | controller -> localhost | changed: "/var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/work/artifacts" 2025-10-09 00:22:52.695252 | controller -> localhost | changed: "/var/lib/zuul/builds/55282bcdc15c456a8088518c38e79147/work/docs" 2025-10-09 00:22:52.706159 | 2025-10-09 00:22:52.706280 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-09 00:22:53.969136 | controller | changed: 2025-10-09 00:22:53.969395 | controller | .d..t...... ./ 2025-10-09 00:22:53.969436 | controller | cd+++++++++ controller/ 2025-10-09 00:22:53.969487 | controller | changed: All items complete 2025-10-09 00:22:53.969517 | 2025-10-09 00:22:55.069205 | controller | changed: .d..t...... ./ 2025-10-09 00:22:56.129172 | controller | changed: .d..t...... ./ 2025-10-09 00:22:56.155011 | 2025-10-09 00:22:56.155179 | TASK [include_role : fetch-output-openshift] 2025-10-09 00:22:56.181359 | controller | skipping: Conditional result was False 2025-10-09 00:22:56.192548 | 2025-10-09 00:22:56.192685 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-09 00:22:56.240085 | controller | skipping: Conditional result was False 2025-10-09 00:22:56.257403 | controller | skipping: Conditional result was False 2025-10-09 00:22:56.316136 | 2025-10-09 00:22:56.316281 | PLAY [localhost] 2025-10-09 00:22:56.335913 | 2025-10-09 00:22:56.336043 | TASK [Run Zuul manifest role] 2025-10-09 00:22:56.356251 | localhost | ok 2025-10-09 00:22:56.373987 | 2025-10-09 00:22:56.374132 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-09 00:22:56.825053 | localhost | changed 2025-10-09 00:22:56.833973 | 2025-10-09 00:22:56.834140 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-09 00:22:56.871242 | localhost | ok 2025-10-09 00:22:56.881059 | 2025-10-09 00:22:56.881181 | TASK [Set zuul-log-path fact] 2025-10-09 00:22:56.904457 | localhost | ok 2025-10-09 00:22:56.928308 | 2025-10-09 00:22:56.928458 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-09 00:22:56.963241 | localhost | ok 2025-10-09 00:22:56.972894 | 2025-10-09 00:22:56.972958 | LOOP [Run upload-logs-swift role] 2025-10-09 00:22:56.997308 | localhost | Output suppressed because no_log was given 2025-10-09 00:22:57.024475 | 2025-10-09 00:22:57.024580 | TASK [Set zuul-log-path fact] 2025-10-09 00:22:57.048988 | localhost | skipping: Conditional result was False 2025-10-09 00:22:57.055730 | 2025-10-09 00:22:57.055803 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-09 00:22:57.529353 | localhost -> localhost | ok: Runtime: 0:00:00.010927 2025-10-09 00:22:57.546194 | 2025-10-09 00:22:57.546362 | TASK [upload-logs-swift : Upload logs to swift]