2025-11-06 00:17:44.198133 | Job console starting... 2025-11-06 00:17:44.211118 | Updating repositories 2025-11-06 00:17:44.326909 | Preparing job workspace 2025-11-06 00:17:48.515429 | Running Ansible setup... 2025-11-06 00:17:55.132043 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-06 00:17:55.825009 | 2025-11-06 00:17:55.825154 | PLAY [localhost] 2025-11-06 00:17:55.836634 | 2025-11-06 00:17:55.836750 | TASK [Gathering Facts] 2025-11-06 00:17:56.791295 | localhost | ok 2025-11-06 00:17:56.807286 | 2025-11-06 00:17:56.807421 | TASK [Setup log path fact] 2025-11-06 00:17:56.826172 | localhost | ok 2025-11-06 00:17:56.839981 | 2025-11-06 00:17:56.840118 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-06 00:17:56.868918 | localhost | ok 2025-11-06 00:17:56.878556 | 2025-11-06 00:17:56.878674 | TASK [emit-job-header : Print job information] 2025-11-06 00:17:56.917769 | # Job Information 2025-11-06 00:17:56.917931 | Ansible Version: 2.15.12 2025-11-06 00:17:56.917964 | Job: ansible-test-sanity-docker-milestone 2025-11-06 00:17:56.917988 | Pipeline: periodic 2025-11-06 00:17:56.918007 | Executor: ze03.softwarefactory-project.io 2025-11-06 00:17:56.918026 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-06 00:17:56.918049 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/3a4/ansible/3a41edb756c349e19785f80f8102027f/ 2025-11-06 00:17:56.918070 | Event ID: 06b8e19d0def49e3b59e004861f83875 2025-11-06 00:17:56.922217 | 2025-11-06 00:17:56.922342 | LOOP [emit-job-header : Print node information] 2025-11-06 00:17:57.026322 | localhost | ok: 2025-11-06 00:17:57.026522 | localhost | # Node Information 2025-11-06 00:17:57.026555 | localhost | Inventory Hostname: controller 2025-11-06 00:17:57.026583 | localhost | Hostname: ip-172-16-158-147 2025-11-06 00:17:57.026610 | localhost | Username: zuul-worker 2025-11-06 00:17:57.026637 | localhost | Distro: Fedora 37 2025-11-06 00:17:57.026656 | localhost | Provider: ansible-us-east-2 2025-11-06 00:17:57.026675 | localhost | Region: us-east-2 2025-11-06 00:17:57.026693 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-06 00:17:57.026711 | localhost | Product Name: t3.small 2025-11-06 00:17:57.026757 | localhost | Interface IP: 3.131.95.19 2025-11-06 00:17:57.035709 | 2025-11-06 00:17:57.035802 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-06 00:17:57.427865 | localhost -> localhost | changed 2025-11-06 00:17:57.434103 | 2025-11-06 00:17:57.434211 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-06 00:17:58.317965 | localhost -> localhost | changed 2025-11-06 00:17:58.359915 | 2025-11-06 00:17:58.360045 | PLAY [all:!appliance*] 2025-11-06 00:17:58.385364 | 2025-11-06 00:17:58.385511 | TASK [include_role : start-zuul-console] 2025-11-06 00:17:58.405607 | controller | ok 2025-11-06 00:17:58.423272 | 2025-11-06 00:17:58.423431 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-06 00:17:59.123252 | controller | ok 2025-11-06 00:17:59.144249 | 2025-11-06 00:17:59.144419 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-06 00:18:01.034644 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-06 00:18:01.045225 | 2025-11-06 00:18:01.045357 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-06 00:18:01.197594 | controller | skipping: Conditional result was False 2025-11-06 00:18:01.204653 | 2025-11-06 00:18:01.204747 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-06 00:18:01.249504 | controller | skipping: Conditional result was False 2025-11-06 00:18:01.255541 | 2025-11-06 00:18:01.255611 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-06 00:18:01.280608 | controller | skipping: Conditional result was False 2025-11-06 00:18:01.287353 | 2025-11-06 00:18:01.287434 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-06 00:18:01.313448 | controller | skipping: Conditional result was False 2025-11-06 00:18:01.320333 | 2025-11-06 00:18:01.320420 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-06 00:18:01.345879 | controller | skipping: Conditional result was False 2025-11-06 00:18:01.352287 | 2025-11-06 00:18:01.352372 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-06 00:18:01.377947 | controller | skipping: Conditional result was False 2025-11-06 00:18:01.398290 | 2025-11-06 00:18:01.398416 | TASK [Disable Fedora Modular] 2025-11-06 00:18:03.171106 | controller | changed 2025-11-06 00:18:03.176911 | 2025-11-06 00:18:03.176990 | TASK [Enable EPEL] 2025-11-06 00:18:03.191594 | controller | skipping: Conditional result was False 2025-11-06 00:18:03.199010 | 2025-11-06 00:18:03.199087 | TASK [Register the RHEL node] 2025-11-06 00:18:03.369223 | 2025-11-06 00:18:03.369469 | TASK [Show the subscription-manager status] 2025-11-06 00:18:03.570521 | controller | skipping: Conditional result was False 2025-11-06 00:18:03.580582 | 2025-11-06 00:18:03.580715 | TASK [Enable EPEL on RHEL] 2025-11-06 00:18:03.799462 | controller | skipping: Conditional result was False 2025-11-06 00:18:03.810942 | 2025-11-06 00:18:03.811075 | TASK [Install git and tox] 2025-11-06 00:19:43.826305 | controller | changed 2025-11-06 00:19:43.836973 | 2025-11-06 00:19:43.837105 | TASK [include_role : prepare-workspace] 2025-11-06 00:19:43.869544 | controller | ok 2025-11-06 00:19:43.897709 | 2025-11-06 00:19:43.897865 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-06 00:19:44.431371 | controller | ok 2025-11-06 00:19:44.440041 | 2025-11-06 00:19:44.440164 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-06 00:19:57.335426 | controller | Output suppressed because no_log was given 2025-11-06 00:19:57.346651 | 2025-11-06 00:19:57.346801 | TASK [include_role : prepare-workspace-openshift] 2025-11-06 00:19:57.361919 | controller | skipping: Conditional result was False 2025-11-06 00:19:57.408180 | 2025-11-06 00:19:57.408254 | PLAY [all:!appliance] 2025-11-06 00:19:57.422816 | 2025-11-06 00:19:57.422897 | TASK [Run add-build-sshkey role (RSA)] 2025-11-06 00:19:57.453035 | controller | ok 2025-11-06 00:19:57.466914 | 2025-11-06 00:19:57.467004 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-06 00:19:57.676514 | controller -> localhost | ok 2025-11-06 00:19:57.683866 | 2025-11-06 00:19:57.683967 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-06 00:19:57.705000 | controller | ok 2025-11-06 00:19:57.719485 | controller | included: /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-06 00:19:57.725664 | 2025-11-06 00:19:57.725759 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-06 00:19:58.251400 | controller -> localhost | Generating public/private rsa key pair. 2025-11-06 00:19:58.251596 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/work/3a41edb756c349e19785f80f8102027f_id_rsa. 2025-11-06 00:19:58.251834 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/work/3a41edb756c349e19785f80f8102027f_id_rsa.pub. 2025-11-06 00:19:58.251863 | controller -> localhost | The key fingerprint is: 2025-11-06 00:19:58.251888 | controller -> localhost | SHA256:cAnISYGMu2uLk7h6TQCS1OxYVM9mw6HXpdNm19w97TM zuul-build-sshkey 2025-11-06 00:19:58.251912 | controller -> localhost | The key's randomart image is: 2025-11-06 00:19:58.251936 | controller -> localhost | +---[RSA 2048]----+ 2025-11-06 00:19:58.251959 | controller -> localhost | |.=+=+=.. . | 2025-11-06 00:19:58.251981 | controller -> localhost | |= o++ =.o.+ o +| 2025-11-06 00:19:58.252005 | controller -> localhost | |.o+ ..Oo+ + . ++| 2025-11-06 00:19:58.252028 | controller -> localhost | |.... +o. + . ..| 2025-11-06 00:19:58.252050 | controller -> localhost | | . . S E.| 2025-11-06 00:19:58.252084 | controller -> localhost | |. . o| 2025-11-06 00:19:58.252112 | controller -> localhost | |.o o | 2025-11-06 00:19:58.252137 | controller -> localhost | |*.. . | 2025-11-06 00:19:58.252160 | controller -> localhost | |*=. | 2025-11-06 00:19:58.252186 | controller -> localhost | +----[SHA256]-----+ 2025-11-06 00:19:58.252245 | controller -> localhost | ok: Runtime: 0:00:00.108125 2025-11-06 00:19:58.259296 | 2025-11-06 00:19:58.259400 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-06 00:19:58.281635 | controller | ok 2025-11-06 00:19:58.291784 | controller | included: /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-06 00:19:58.301895 | 2025-11-06 00:19:58.301990 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-06 00:19:58.316686 | controller | skipping: Conditional result was False 2025-11-06 00:19:58.324147 | 2025-11-06 00:19:58.324253 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-06 00:19:59.028712 | controller | changed 2025-11-06 00:19:59.036855 | 2025-11-06 00:19:59.036997 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-06 00:19:59.393001 | controller | ok 2025-11-06 00:19:59.405344 | 2025-11-06 00:19:59.405480 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-06 00:20:00.938440 | controller | changed 2025-11-06 00:20:00.945319 | 2025-11-06 00:20:00.945431 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-06 00:20:03.897329 | controller | changed 2025-11-06 00:20:03.913236 | 2025-11-06 00:20:03.913429 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-06 00:20:03.942181 | controller | skipping: Conditional result was False 2025-11-06 00:20:03.959967 | 2025-11-06 00:20:03.960201 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-06 00:20:04.385224 | controller -> localhost | changed 2025-11-06 00:20:04.398376 | 2025-11-06 00:20:04.398791 | TASK [add-build-sshkey : Add back temp key] 2025-11-06 00:20:04.730382 | controller -> localhost | Identity added: /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/work/3a41edb756c349e19785f80f8102027f_id_rsa (zuul-build-sshkey) 2025-11-06 00:20:04.730627 | controller -> localhost | ok: Runtime: 0:00:00.008303 2025-11-06 00:20:04.737532 | 2025-11-06 00:20:04.737619 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-06 00:20:05.713979 | controller | ok 2025-11-06 00:20:05.721475 | 2025-11-06 00:20:05.721559 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-06 00:20:05.747021 | controller | skipping: Conditional result was False 2025-11-06 00:20:05.762447 | 2025-11-06 00:20:05.762561 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-06 00:20:05.794130 | controller | ok 2025-11-06 00:20:05.817067 | 2025-11-06 00:20:05.817277 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-06 00:20:06.077593 | controller -> localhost | ok 2025-11-06 00:20:06.086776 | 2025-11-06 00:20:06.086921 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-06 00:20:06.118072 | controller | ok 2025-11-06 00:20:06.133216 | controller | included: /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-06 00:20:06.141673 | 2025-11-06 00:20:06.141807 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-06 00:20:06.435276 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-06 00:20:06.435471 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/work/3a41edb756c349e19785f80f8102027f_id_ecdsa. 2025-11-06 00:20:06.435500 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/work/3a41edb756c349e19785f80f8102027f_id_ecdsa.pub. 2025-11-06 00:20:06.435531 | controller -> localhost | The key fingerprint is: 2025-11-06 00:20:06.435552 | controller -> localhost | SHA256:dtpV+VvIBx5v3+9UD0vQ2tTB7oazyDMFt61CpK0Gikw zuul-build-sshkey 2025-11-06 00:20:06.435572 | controller -> localhost | The key's randomart image is: 2025-11-06 00:20:06.435591 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-06 00:20:06.435610 | controller -> localhost | | .. | 2025-11-06 00:20:06.435628 | controller -> localhost | | . +.| 2025-11-06 00:20:06.435746 | controller -> localhost | | . O .| 2025-11-06 00:20:06.435780 | controller -> localhost | | o X B | 2025-11-06 00:20:06.435800 | controller -> localhost | | S = = % B| 2025-11-06 00:20:06.435818 | controller -> localhost | | E o = + * OB| 2025-11-06 00:20:06.435836 | controller -> localhost | | o . . o = o *.=| 2025-11-06 00:20:06.435853 | controller -> localhost | | o . o * o ..| 2025-11-06 00:20:06.435871 | controller -> localhost | | . + .o| 2025-11-06 00:20:06.435888 | controller -> localhost | +----[SHA256]-----+ 2025-11-06 00:20:06.435931 | controller -> localhost | ok: Runtime: 0:00:00.011373 2025-11-06 00:20:06.443179 | 2025-11-06 00:20:06.443251 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-06 00:20:06.472659 | controller | ok 2025-11-06 00:20:06.480495 | controller | included: /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-06 00:20:06.489876 | 2025-11-06 00:20:06.489983 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-06 00:20:06.514870 | controller | skipping: Conditional result was False 2025-11-06 00:20:06.521158 | 2025-11-06 00:20:06.521233 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-06 00:20:07.040705 | controller | changed 2025-11-06 00:20:07.058674 | 2025-11-06 00:20:07.058871 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-06 00:20:07.443706 | controller | ok 2025-11-06 00:20:07.450009 | 2025-11-06 00:20:07.450140 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-06 00:20:08.966933 | controller | changed 2025-11-06 00:20:08.985246 | 2025-11-06 00:20:08.985393 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-06 00:20:10.446830 | controller | changed 2025-11-06 00:20:10.463193 | 2025-11-06 00:20:10.463359 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-06 00:20:10.491389 | controller | skipping: Conditional result was False 2025-11-06 00:20:10.500789 | 2025-11-06 00:20:10.500886 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-06 00:20:10.739448 | controller -> localhost | changed 2025-11-06 00:20:10.785766 | 2025-11-06 00:20:10.785887 | TASK [add-build-sshkey : Add back temp key] 2025-11-06 00:20:11.045123 | controller -> localhost | Identity added: /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/work/3a41edb756c349e19785f80f8102027f_id_ecdsa (zuul-build-sshkey) 2025-11-06 00:20:11.045406 | controller -> localhost | ok: Runtime: 0:00:00.006867 2025-11-06 00:20:11.057775 | 2025-11-06 00:20:11.057910 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-06 00:20:11.393770 | controller | ok 2025-11-06 00:20:11.404577 | 2025-11-06 00:20:11.404702 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-06 00:20:11.440655 | controller | skipping: Conditional result was False 2025-11-06 00:20:11.455151 | 2025-11-06 00:20:11.455287 | TASK [include_role : remove-zuul-sshkey] 2025-11-06 00:20:11.480868 | controller | skipping: Conditional result was False 2025-11-06 00:20:11.491461 | 2025-11-06 00:20:11.491634 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-06 00:20:11.932707 | controller | ok: "logs" 2025-11-06 00:20:11.933294 | controller | ok: All items complete 2025-11-06 00:20:11.933342 | 2025-11-06 00:20:12.324152 | controller | ok: "artifacts" 2025-11-06 00:20:12.676145 | controller | ok: "docs" 2025-11-06 00:20:12.687236 | 2025-11-06 00:20:12.687354 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-06 00:20:13.085483 | controller | changed: "logs" 2025-11-06 00:20:13.451876 | controller | changed: "artifacts" 2025-11-06 00:20:13.783209 | controller | changed: "docs" 2025-11-06 00:20:13.875847 | 2025-11-06 00:20:13.875944 | PLAY RECAP 2025-11-06 00:20:13.875988 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-06 00:20:13.876014 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-06 00:20:13.876032 | 2025-11-06 00:20:13.997617 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-06 00:20:13.998519 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-06 00:20:14.601871 | 2025-11-06 00:20:14.602025 | PLAY [all] 2025-11-06 00:20:14.628503 | 2025-11-06 00:20:14.628647 | TASK [Install binary dependencies] 2025-11-06 00:20:14.680260 | controller | ok 2025-11-06 00:20:14.700012 | 2025-11-06 00:20:14.700264 | TASK [bindep : Include find tasks] 2025-11-06 00:20:14.729620 | controller | ok 2025-11-06 00:20:14.738711 | controller | included: /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-06 00:20:14.745777 | 2025-11-06 00:20:14.745875 | TASK [bindep : Look for bindep.txt] 2025-11-06 00:20:15.344199 | controller | ok 2025-11-06 00:20:15.358298 | 2025-11-06 00:20:15.358491 | TASK [bindep : Define bindep_file fact] 2025-11-06 00:20:15.374456 | controller | skipping: Conditional result was False 2025-11-06 00:20:15.380666 | 2025-11-06 00:20:15.380789 | TASK [bindep : Look for other-requirements.txt] 2025-11-06 00:20:15.688937 | controller | ok 2025-11-06 00:20:15.696904 | 2025-11-06 00:20:15.697007 | TASK [bindep : Define bindep_file fact] 2025-11-06 00:20:15.732059 | controller | skipping: Conditional result was False 2025-11-06 00:20:15.747118 | 2025-11-06 00:20:15.747284 | TASK [bindep : Look for bindep fallback file] 2025-11-06 00:20:15.784672 | controller | skipping: Conditional result was False 2025-11-06 00:20:15.794467 | 2025-11-06 00:20:15.794575 | TASK [bindep : Define bindep_file fact] 2025-11-06 00:20:15.819219 | controller | skipping: Conditional result was False 2025-11-06 00:20:15.825316 | 2025-11-06 00:20:15.825402 | TASK [bindep : Include bindep tasks] 2025-11-06 00:20:15.849652 | controller | skipping: Conditional result was False 2025-11-06 00:20:15.857484 | 2025-11-06 00:20:15.857594 | TASK [bindep : Include install tasks] 2025-11-06 00:20:15.882367 | controller | skipping: Conditional result was False 2025-11-06 00:20:15.888344 | 2025-11-06 00:20:15.888415 | LOOP [bindep : Include package tasks] 2025-11-06 00:20:15.949818 | 2025-11-06 00:20:15.949992 | TASK [Run test-setup role] 2025-11-06 00:20:15.970240 | controller | ok 2025-11-06 00:20:15.993706 | 2025-11-06 00:20:15.993892 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-06 00:20:16.332005 | controller | ok 2025-11-06 00:20:16.341809 | 2025-11-06 00:20:16.341919 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-06 00:20:16.490661 | controller | skipping: Conditional result was False 2025-11-06 00:20:16.535790 | 2025-11-06 00:20:16.535876 | PLAY RECAP 2025-11-06 00:20:16.535919 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-06 00:20:16.535941 | 2025-11-06 00:20:16.642052 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-06 00:20:16.643255 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-06 00:20:17.254143 | 2025-11-06 00:20:17.254284 | PLAY [controller] 2025-11-06 00:20:17.275413 | 2025-11-06 00:20:17.275547 | TASK [Create the /root directory] 2025-11-06 00:20:17.994834 | controller | ok 2025-11-06 00:20:18.002686 | 2025-11-06 00:20:18.002836 | TASK [Install glibc-langpack-en] 2025-11-06 00:20:26.148768 | controller | ok: Nothing to do 2025-11-06 00:20:26.154490 | 2025-11-06 00:20:26.154603 | TASK [Ensure controller directory exists] 2025-11-06 00:20:26.630043 | controller | changed 2025-11-06 00:20:26.650715 | 2025-11-06 00:20:26.660119 | TASK [Install container runtime] 2025-11-06 00:20:26.730569 | controller | ok 2025-11-06 00:20:26.828513 | 2025-11-06 00:20:26.828657 | LOOP [ensure-podman : Find distribution installation] 2025-11-06 00:20:26.894330 | controller | ok: "/var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-06 00:20:26.910139 | controller | included: /var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-06 00:20:26.919280 | 2025-11-06 00:20:26.919416 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-06 00:21:55.927998 | controller | changed 2025-11-06 00:21:55.934632 | 2025-11-06 00:21:55.934705 | TASK [ensure-podman : Fetch podman version] 2025-11-06 00:21:56.689668 | controller | Client: Podman Engine 2025-11-06 00:21:56.727913 | controller | Version: 4.6.2 2025-11-06 00:21:56.727951 | controller | API Version: 4.6.2 2025-11-06 00:21:56.727958 | controller | Go Version: go1.19.12 2025-11-06 00:21:56.727975 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-06 00:21:56.727983 | controller | OS/Arch: linux/amd64 2025-11-06 00:21:57.077692 | controller | ok: Runtime: 0:00:00.251122 2025-11-06 00:21:57.092060 | 2025-11-06 00:21:57.092243 | TASK [ensure-podman : Print podman version installed] 2025-11-06 00:21:57.131477 | Podman version: Client: Podman Engine 2025-11-06 00:21:57.131778 | Version: 4.6.2 2025-11-06 00:21:57.131853 | API Version: 4.6.2 2025-11-06 00:21:57.131902 | Go Version: go1.19.12 2025-11-06 00:21:57.131946 | Built: Mon Aug 28 19:38:31 2023 2025-11-06 00:21:57.131991 | OS/Arch: linux/amd64 2025-11-06 00:21:57.144863 | 2025-11-06 00:21:57.145017 | TASK [ensure-podman : Validate podman engine] 2025-11-06 00:21:57.285233 | controller | skipping: Conditional result was False 2025-11-06 00:21:57.294783 | 2025-11-06 00:21:57.294922 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-06 00:21:57.309705 | controller | skipping: Conditional result was False 2025-11-06 00:21:57.326699 | 2025-11-06 00:21:57.326844 | TASK [Ensure python3.8 is present] 2025-11-06 00:21:57.342373 | controller | skipping: Conditional result was False 2025-11-06 00:21:57.351942 | 2025-11-06 00:21:57.352091 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-06 00:21:57.375217 | controller | ok 2025-11-06 00:21:57.405069 | 2025-11-06 00:21:57.405191 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-06 00:22:01.436035 | controller | ok: Nothing to do 2025-11-06 00:22:01.443701 | 2025-11-06 00:22:01.443819 | TASK [our-ensure-python : Also install python3-devel] 2025-11-06 00:22:16.384408 | controller | changed 2025-11-06 00:22:16.395615 | 2025-11-06 00:22:16.395758 | TASK [Run ensure-virtualenv role] 2025-11-06 00:22:16.415979 | controller | ok 2025-11-06 00:22:16.441323 | 2025-11-06 00:22:16.441460 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-06 00:22:16.907244 | controller | /usr/bin/virtualenv 2025-11-06 00:22:17.080741 | controller | ok: Runtime: 0:00:00.004657 2025-11-06 00:22:17.087602 | 2025-11-06 00:22:17.087706 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-06 00:22:17.112380 | controller | skipping: Conditional result was False 2025-11-06 00:22:17.113021 | controller | ok: All items complete 2025-11-06 00:22:17.113077 | 2025-11-06 00:22:17.135952 | 2025-11-06 00:22:17.136106 | TASK [Find the full path of the Python interpreter] 2025-11-06 00:22:17.612570 | controller | /usr/bin/python3 2025-11-06 00:22:17.814453 | controller | ok 2025-11-06 00:22:17.820157 | 2025-11-06 00:22:17.820254 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-06 00:22:19.215027 | controller | created virtual environment CPython3.11.0.final.0-64 in 762ms 2025-11-06 00:22:19.272388 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-06 00:22:19.272446 | 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-11-06 00:22:19.272465 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-06 00:22:19.272490 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-06 00:22:19.471051 | controller | changed 2025-11-06 00:22:19.478036 | 2025-11-06 00:22:19.478132 | TASK [Set selinux package] 2025-11-06 00:22:19.508502 | controller | ok 2025-11-06 00:22:19.514235 | 2025-11-06 00:22:19.514337 | TASK [Set selinux package (Fedora)] 2025-11-06 00:22:19.557741 | controller | ok 2025-11-06 00:22:19.566615 | 2025-11-06 00:22:19.566796 | TASK [Install selinux into virtualenv] 2025-11-06 00:22:22.172295 | controller | Collecting selinux-please-lie-to-me 2025-11-06 00:22:22.265611 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-06 00:22:22.791462 | controller | Collecting setuptools<50.0.0 2025-11-06 00:22:22.822775 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-06 00:22:22.946214 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00 2025-11-06 00:22:23.101020 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-06 00:22:23.101339 | controller | Attempting uninstall: setuptools 2025-11-06 00:22:23.106206 | controller | Found existing installation: setuptools 62.6.0 2025-11-06 00:22:23.219334 | controller | Uninstalling setuptools-62.6.0: 2025-11-06 00:22:23.234486 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-06 00:22:24.001647 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-06 00:22:24.210783 | controller | 2025-11-06 00:22:24.427987 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-06 00:22:24.428037 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-06 00:22:24.747544 | controller | ok: Runtime: 0:00:04.396295 2025-11-06 00:22:24.756981 | 2025-11-06 00:22:24.757091 | TASK [Install pytest-forked into virtualenv] 2025-11-06 00:22:25.973285 | controller | Collecting pytest-forked 2025-11-06 00:22:26.058113 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-06 00:22:26.117005 | controller | Collecting py 2025-11-06 00:22:26.134629 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-06 00:22:26.165978 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.5 MB/s eta 0:00:00 2025-11-06 00:22:26.350845 | controller | Collecting pytest>=3.10 2025-11-06 00:22:26.362927 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-11-06 00:22:26.400374 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 10.8 MB/s eta 0:00:00 2025-11-06 00:22:26.456843 | controller | Collecting iniconfig>=1 2025-11-06 00:22:26.469485 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-06 00:22:26.538002 | controller | Collecting packaging>=20 2025-11-06 00:22:26.551810 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-06 00:22:26.560509 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.9 MB/s eta 0:00:00 2025-11-06 00:22:26.605639 | controller | Collecting pluggy<2,>=1.5 2025-11-06 00:22:26.619437 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-06 00:22:26.693292 | controller | Collecting pygments>=2.7.2 2025-11-06 00:22:26.705656 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-06 00:22:26.732025 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 53.7 MB/s eta 0:00:00 2025-11-06 00:22:26.863030 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-06 00:22:29.159052 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0 2025-11-06 00:22:29.178772 | controller | 2025-11-06 00:22:29.425420 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-06 00:22:29.426162 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-06 00:22:29.931413 | controller | ok: Runtime: 0:00:04.187313 2025-11-06 00:22:29.943836 | 2025-11-06 00:22:29.944039 | TASK [Update pip] 2025-11-06 00:22:31.019837 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-06 00:22:31.292730 | controller | Collecting pip 2025-11-06 00:22:31.461086 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-06 00:22:31.630568 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.8 MB/s eta 0:00:00 2025-11-06 00:22:31.783436 | controller | Installing collected packages: pip 2025-11-06 00:22:31.783865 | controller | Attempting uninstall: pip 2025-11-06 00:22:31.788478 | controller | Found existing installation: pip 22.2.2 2025-11-06 00:22:32.049047 | controller | Uninstalling pip-22.2.2: 2025-11-06 00:22:32.078791 | controller | Successfully uninstalled pip-22.2.2 2025-11-06 00:22:33.819715 | controller | Successfully installed pip-25.3 2025-11-06 00:22:34.102902 | controller | ok: Runtime: 0:00:03.597822 2025-11-06 00:22:34.110808 | 2025-11-06 00:22:34.110938 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-06 00:22:34.630370 | controller | changed 2025-11-06 00:22:34.636175 | 2025-11-06 00:22:34.636245 | TASK [Install ansible into virtualenv] 2025-11-06 00:22:35.624034 | controller | Processing ./src/github.com/ansible/ansible 2025-11-06 00:22:35.630426 | controller | Installing build dependencies: started 2025-11-06 00:22:37.569254 | controller | Installing build dependencies: finished with status 'done' 2025-11-06 00:22:37.570470 | controller | Getting requirements to build wheel: started 2025-11-06 00:22:39.103258 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-06 00:22:39.104698 | controller | Preparing metadata (pyproject.toml): started 2025-11-06 00:22:40.033252 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-06 00:22:40.038245 | 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-11-06 00:22:40.043160 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-06 00:22:40.271332 | controller | ERROR 2025-11-06 00:22:40.271595 | controller | { 2025-11-06 00:22:40.271636 | controller | "delta": "0:00:05.146054", 2025-11-06 00:22:40.271822 | controller | "end": "2025-11-06 00:22:40.196064", 2025-11-06 00:22:40.271851 | controller | "msg": "non-zero return code", 2025-11-06 00:22:40.271887 | controller | "rc": 1, 2025-11-06 00:22:40.271905 | controller | "start": "2025-11-06 00:22:35.050010" 2025-11-06 00:22:40.271921 | controller | } failure 2025-11-06 00:22:40.274617 | 2025-11-06 00:22:40.274827 | PLAY RECAP 2025-11-06 00:22:40.274979 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-06 00:22:40.275008 | 2025-11-06 00:22:40.422683 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-06 00:22:40.423995 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-06 00:22:41.040918 | 2025-11-06 00:22:41.041038 | PLAY [all] 2025-11-06 00:22:41.062972 | 2025-11-06 00:22:41.063134 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-06 00:22:41.879551 | controller | changed: non-zero return code 2025-11-06 00:22:41.893205 | 2025-11-06 00:22:41.893421 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-06 00:22:41.922162 | controller | skipping: Conditional result was False 2025-11-06 00:22:41.936351 | 2025-11-06 00:22:41.936533 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-06 00:22:41.977180 | 2025-11-06 00:22:41.977453 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-06 00:22:42.010486 | 2025-11-06 00:22:42.010649 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-06 00:22:42.035962 | controller | skipping: Conditional result was False 2025-11-06 00:22:42.050989 | 2025-11-06 00:22:42.051167 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-06 00:22:42.088906 | 2025-11-06 00:22:42.089112 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-06 00:22:42.114669 | controller | skipping: Conditional result was False 2025-11-06 00:22:42.123302 | 2025-11-06 00:22:42.123396 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-06 00:22:42.148479 | controller | skipping: Conditional result was False 2025-11-06 00:22:42.158248 | 2025-11-06 00:22:42.158399 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-06 00:22:42.184494 | controller | skipping: Conditional result was False 2025-11-06 00:22:42.225764 | 2025-11-06 00:22:42.225874 | PLAY RECAP 2025-11-06 00:22:42.225927 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-06 00:22:42.225957 | 2025-11-06 00:22:42.328011 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-06 00:22:42.329094 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-06 00:22:42.922046 | 2025-11-06 00:22:42.922164 | PLAY [all:!appliance*] 2025-11-06 00:22:42.943418 | 2025-11-06 00:22:42.943521 | TASK [unregister the node] 2025-11-06 00:22:43.086154 | controller | skipping: Conditional result was False 2025-11-06 00:22:43.092374 | 2025-11-06 00:22:43.092482 | TASK [include_role : fetch-output] 2025-11-06 00:22:43.122120 | controller | ok 2025-11-06 00:22:43.141553 | 2025-11-06 00:22:43.141673 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-06 00:22:43.186360 | controller | skipping: Conditional result was False 2025-11-06 00:22:43.192867 | 2025-11-06 00:22:43.192978 | TASK [fetch-output : Set log path for single node] 2025-11-06 00:22:43.222651 | controller | ok 2025-11-06 00:22:43.228705 | 2025-11-06 00:22:43.228835 | LOOP [fetch-output : Ensure local output dirs] 2025-11-06 00:22:43.669900 | controller -> localhost | ok: "/var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/work/logs" 2025-11-06 00:22:43.919202 | controller -> localhost | changed: "/var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/work/artifacts" 2025-11-06 00:22:44.148952 | controller -> localhost | changed: "/var/lib/zuul/builds/3a41edb756c349e19785f80f8102027f/work/docs" 2025-11-06 00:22:44.168139 | 2025-11-06 00:22:44.168311 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-06 00:22:45.406178 | controller | changed: 2025-11-06 00:22:45.406560 | controller | .d..t...... ./ 2025-11-06 00:22:45.406601 | controller | cd+++++++++ controller/ 2025-11-06 00:22:45.406657 | controller | changed: All items complete 2025-11-06 00:22:45.406687 | 2025-11-06 00:22:46.473679 | controller | changed: .d..t...... ./ 2025-11-06 00:22:47.459657 | controller | changed: .d..t...... ./ 2025-11-06 00:22:47.490481 | 2025-11-06 00:22:47.490678 | TASK [include_role : fetch-output-openshift] 2025-11-06 00:22:47.507301 | controller | skipping: Conditional result was False 2025-11-06 00:22:47.517691 | 2025-11-06 00:22:47.517867 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-06 00:22:47.558536 | controller | skipping: Conditional result was False 2025-11-06 00:22:47.569846 | controller | skipping: Conditional result was False 2025-11-06 00:22:47.610630 | 2025-11-06 00:22:47.610765 | PLAY [localhost] 2025-11-06 00:22:47.625117 | 2025-11-06 00:22:47.625259 | TASK [Run Zuul manifest role] 2025-11-06 00:22:47.644420 | localhost | ok 2025-11-06 00:22:47.659409 | 2025-11-06 00:22:47.659540 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-06 00:22:48.056213 | localhost | changed 2025-11-06 00:22:48.061770 | 2025-11-06 00:22:48.061845 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-06 00:22:48.091349 | localhost | ok 2025-11-06 00:22:48.099791 | 2025-11-06 00:22:48.099891 | TASK [Set zuul-log-path fact] 2025-11-06 00:22:48.119437 | localhost | ok 2025-11-06 00:22:48.135515 | 2025-11-06 00:22:48.135654 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-06 00:22:48.165170 | localhost | ok 2025-11-06 00:22:48.176181 | 2025-11-06 00:22:48.176314 | LOOP [Run upload-logs-swift role] 2025-11-06 00:22:48.204035 | localhost | Output suppressed because no_log was given 2025-11-06 00:22:48.234715 | 2025-11-06 00:22:48.234878 | TASK [Set zuul-log-path fact] 2025-11-06 00:22:48.259898 | localhost | skipping: Conditional result was False 2025-11-06 00:22:48.265809 | 2025-11-06 00:22:48.265942 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-06 00:22:48.733840 | localhost -> localhost | ok: Runtime: 0:00:00.009707 2025-11-06 00:22:48.750113 | 2025-11-06 00:22:48.750303 | TASK [upload-logs-swift : Upload logs to swift]