2025-12-18 00:15:05.198915 | Job console starting... 2025-12-18 00:15:05.211139 | Updating repositories 2025-12-18 00:15:05.383179 | Preparing job workspace 2025-12-18 00:15:09.078355 | Running Ansible setup... 2025-12-18 00:15:14.641004 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-18 00:15:15.306987 | 2025-12-18 00:15:15.307123 | PLAY [localhost] 2025-12-18 00:15:15.316932 | 2025-12-18 00:15:15.317075 | TASK [Gathering Facts] 2025-12-18 00:15:16.320620 | localhost | ok 2025-12-18 00:15:16.341947 | 2025-12-18 00:15:16.342110 | TASK [Setup log path fact] 2025-12-18 00:15:16.363335 | localhost | ok 2025-12-18 00:15:16.377493 | 2025-12-18 00:15:16.377612 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-18 00:15:16.419008 | localhost | ok 2025-12-18 00:15:16.432058 | 2025-12-18 00:15:16.432203 | TASK [emit-job-header : Print job information] 2025-12-18 00:15:16.485070 | # Job Information 2025-12-18 00:15:16.485273 | Ansible Version: 2.15.12 2025-12-18 00:15:16.485331 | Job: ansible-test-sanity-docker-devel 2025-12-18 00:15:16.485373 | Pipeline: periodic 2025-12-18 00:15:16.485405 | Executor: ze02.softwarefactory-project.io 2025-12-18 00:15:16.485431 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-18 00:15:16.485462 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/457/ansible/457ceca442de42219bf1d3d135050d61/ 2025-12-18 00:15:16.485489 | Event ID: 95f00f3203bf47de8d788a25b598cc45 2025-12-18 00:15:16.492392 | 2025-12-18 00:15:16.492486 | LOOP [emit-job-header : Print node information] 2025-12-18 00:15:16.596730 | localhost | ok: 2025-12-18 00:15:16.596920 | localhost | # Node Information 2025-12-18 00:15:16.596957 | localhost | Inventory Hostname: controller 2025-12-18 00:15:16.596986 | localhost | Hostname: np0005564940 2025-12-18 00:15:16.597018 | localhost | Username: zuul 2025-12-18 00:15:16.597051 | localhost | Distro: Fedora 37 2025-12-18 00:15:16.597078 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-18 00:15:16.597100 | localhost | Region: ca-ymq-1 2025-12-18 00:15:16.597121 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-18 00:15:16.597142 | localhost | Product Name: OpenStack Nova 2025-12-18 00:15:16.597166 | localhost | Interface IP: 162.253.55.195 2025-12-18 00:15:16.608895 | 2025-12-18 00:15:16.609060 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-18 00:15:17.020445 | localhost -> localhost | changed 2025-12-18 00:15:17.032953 | 2025-12-18 00:15:17.033120 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-18 00:15:17.988525 | localhost -> localhost | changed 2025-12-18 00:15:18.031912 | 2025-12-18 00:15:18.032010 | PLAY [all:!appliance*] 2025-12-18 00:15:18.056896 | 2025-12-18 00:15:18.057022 | TASK [include_role : start-zuul-console] 2025-12-18 00:15:18.079743 | controller | ok 2025-12-18 00:15:18.100875 | 2025-12-18 00:15:18.101019 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-18 00:15:18.489420 | controller | ok 2025-12-18 00:15:18.503723 | 2025-12-18 00:15:18.503844 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-18 00:15:19.540625 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-18 00:15:19.555018 | 2025-12-18 00:15:19.555150 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-18 00:15:20.104376 | controller | skipping: Conditional result was False 2025-12-18 00:15:20.112095 | 2025-12-18 00:15:20.112183 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-18 00:15:20.157360 | controller | skipping: Conditional result was False 2025-12-18 00:15:20.165112 | 2025-12-18 00:15:20.165223 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-18 00:15:20.180024 | controller | skipping: Conditional result was False 2025-12-18 00:15:20.188193 | 2025-12-18 00:15:20.188299 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-18 00:15:20.202866 | controller | skipping: Conditional result was False 2025-12-18 00:15:20.210602 | 2025-12-18 00:15:20.210723 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-18 00:15:20.234702 | controller | skipping: Conditional result was False 2025-12-18 00:15:20.240899 | 2025-12-18 00:15:20.240972 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-18 00:15:20.266162 | controller | skipping: Conditional result was False 2025-12-18 00:15:20.288410 | 2025-12-18 00:15:20.288532 | TASK [Disable Fedora Modular] 2025-12-18 00:15:20.544748 | controller | changed 2025-12-18 00:15:20.560585 | 2025-12-18 00:15:20.560782 | TASK [Enable EPEL] 2025-12-18 00:15:20.588620 | controller | skipping: Conditional result was False 2025-12-18 00:15:20.597976 | 2025-12-18 00:15:20.598115 | TASK [Register the RHEL node] 2025-12-18 00:15:21.152584 | 2025-12-18 00:15:21.152883 | TASK [Show the subscription-manager status] 2025-12-18 00:15:21.738788 | controller | skipping: Conditional result was False 2025-12-18 00:15:21.745208 | 2025-12-18 00:15:21.745271 | TASK [Enable EPEL on RHEL] 2025-12-18 00:15:22.291517 | controller | skipping: Conditional result was False 2025-12-18 00:15:22.306307 | 2025-12-18 00:15:22.306488 | TASK [Install git and tox] 2025-12-18 00:16:40.720147 | controller | changed 2025-12-18 00:16:40.727055 | 2025-12-18 00:16:40.727124 | TASK [include_role : prepare-workspace] 2025-12-18 00:16:40.766405 | controller | ok 2025-12-18 00:16:40.787788 | 2025-12-18 00:16:40.787878 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-18 00:16:41.027849 | controller | ok 2025-12-18 00:16:41.037568 | 2025-12-18 00:16:41.037731 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-18 00:16:53.759974 | controller | Output suppressed because no_log was given 2025-12-18 00:16:53.786083 | 2025-12-18 00:16:53.786191 | TASK [include_role : prepare-workspace-openshift] 2025-12-18 00:16:53.815957 | controller | skipping: Conditional result was False 2025-12-18 00:16:53.881412 | 2025-12-18 00:16:53.881514 | PLAY [all:!appliance] 2025-12-18 00:16:53.899371 | 2025-12-18 00:16:53.899508 | TASK [Run add-build-sshkey role (RSA)] 2025-12-18 00:16:53.931561 | controller | ok 2025-12-18 00:16:53.946879 | 2025-12-18 00:16:53.946981 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-18 00:16:54.209112 | controller -> localhost | ok 2025-12-18 00:16:54.223218 | 2025-12-18 00:16:54.223346 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-18 00:16:54.276059 | controller | ok 2025-12-18 00:16:54.297246 | controller | included: /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-18 00:16:54.304031 | 2025-12-18 00:16:54.304116 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-18 00:16:54.768134 | controller -> localhost | Generating public/private rsa key pair. 2025-12-18 00:16:54.768559 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/work/457ceca442de42219bf1d3d135050d61_id_rsa. 2025-12-18 00:16:54.768613 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/work/457ceca442de42219bf1d3d135050d61_id_rsa.pub. 2025-12-18 00:16:54.768637 | controller -> localhost | The key fingerprint is: 2025-12-18 00:16:54.768657 | controller -> localhost | SHA256:F4zTvY1yoc50L21/RST019EWvZCDn9dXMmKKNh3+OLI zuul-build-sshkey 2025-12-18 00:16:54.768760 | controller -> localhost | The key's randomart image is: 2025-12-18 00:16:54.768783 | controller -> localhost | +---[RSA 2048]----+ 2025-12-18 00:16:54.768801 | controller -> localhost | | ..oo+| 2025-12-18 00:16:54.768818 | controller -> localhost | | +.oo++.O| 2025-12-18 00:16:54.768835 | controller -> localhost | | o++++.+*B| 2025-12-18 00:16:54.768852 | controller -> localhost | | +.+o B o=| 2025-12-18 00:16:54.768869 | controller -> localhost | | .S.=o= o..| 2025-12-18 00:16:54.768895 | controller -> localhost | | .=o+.o .| 2025-12-18 00:16:54.768950 | controller -> localhost | | oo.. + .| 2025-12-18 00:16:54.769072 | controller -> localhost | | E o ..| 2025-12-18 00:16:54.769118 | controller -> localhost | | o| 2025-12-18 00:16:54.769140 | controller -> localhost | +----[SHA256]-----+ 2025-12-18 00:16:54.769186 | controller -> localhost | ok: Runtime: 0:00:00.083380 2025-12-18 00:16:54.786896 | 2025-12-18 00:16:54.787013 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-18 00:16:54.819502 | controller | ok 2025-12-18 00:16:54.834032 | controller | included: /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-18 00:16:54.848979 | 2025-12-18 00:16:54.849122 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-18 00:16:54.875623 | controller | skipping: Conditional result was False 2025-12-18 00:16:54.885191 | 2025-12-18 00:16:54.885320 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-18 00:16:55.333088 | controller | changed 2025-12-18 00:16:55.339426 | 2025-12-18 00:16:55.339517 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-18 00:16:55.578630 | controller | ok 2025-12-18 00:16:55.588025 | 2025-12-18 00:16:55.588122 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-18 00:16:56.203236 | controller | changed 2025-12-18 00:16:56.214483 | 2025-12-18 00:16:56.214592 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-18 00:16:56.818929 | controller | changed 2025-12-18 00:16:56.825645 | 2025-12-18 00:16:56.825741 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-18 00:16:56.850816 | controller | skipping: Conditional result was False 2025-12-18 00:16:56.858923 | 2025-12-18 00:16:56.859000 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-18 00:16:57.270803 | controller -> localhost | changed 2025-12-18 00:16:57.286992 | 2025-12-18 00:16:57.287139 | TASK [add-build-sshkey : Add back temp key] 2025-12-18 00:16:57.594821 | controller -> localhost | Identity added: /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/work/457ceca442de42219bf1d3d135050d61_id_rsa (zuul-build-sshkey) 2025-12-18 00:16:57.595092 | controller -> localhost | ok: Runtime: 0:00:00.015217 2025-12-18 00:16:57.602260 | 2025-12-18 00:16:57.602332 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-18 00:16:57.948454 | controller | ok 2025-12-18 00:16:57.963158 | 2025-12-18 00:16:57.963346 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-18 00:16:57.991143 | controller | skipping: Conditional result was False 2025-12-18 00:16:58.011585 | 2025-12-18 00:16:58.011745 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-18 00:16:58.035877 | controller | ok 2025-12-18 00:16:58.060456 | 2025-12-18 00:16:58.060558 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-18 00:16:58.279746 | controller -> localhost | ok 2025-12-18 00:16:58.287023 | 2025-12-18 00:16:58.287092 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-18 00:16:58.324570 | controller | ok 2025-12-18 00:16:58.347170 | controller | included: /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-18 00:16:58.356272 | 2025-12-18 00:16:58.356359 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-18 00:16:58.658245 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-18 00:16:58.658720 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/work/457ceca442de42219bf1d3d135050d61_id_ecdsa. 2025-12-18 00:16:58.658793 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/work/457ceca442de42219bf1d3d135050d61_id_ecdsa.pub. 2025-12-18 00:16:58.658855 | controller -> localhost | The key fingerprint is: 2025-12-18 00:16:58.658900 | controller -> localhost | SHA256:mqqDWoz5T6SWVjP3xrMpkLgkgs7PMIeyYUmOie+YA5s zuul-build-sshkey 2025-12-18 00:16:58.658941 | controller -> localhost | The key's randomart image is: 2025-12-18 00:16:58.658980 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-18 00:16:58.659019 | controller -> localhost | | | 2025-12-18 00:16:58.659058 | controller -> localhost | | | 2025-12-18 00:16:58.659096 | controller -> localhost | | | 2025-12-18 00:16:58.659134 | controller -> localhost | | | 2025-12-18 00:16:58.659173 | controller -> localhost | |.. .=.. S | 2025-12-18 00:16:58.659211 | controller -> localhost | |X===o+ = | 2025-12-18 00:16:58.659248 | controller -> localhost | |&&Bo..o = | 2025-12-18 00:16:58.659286 | controller -> localhost | |E&B. ... + | 2025-12-18 00:16:58.659322 | controller -> localhost | |*o**o .o | 2025-12-18 00:16:58.659360 | controller -> localhost | +----[SHA256]-----+ 2025-12-18 00:16:58.659469 | controller -> localhost | ok: Runtime: 0:00:00.012536 2025-12-18 00:16:58.675512 | 2025-12-18 00:16:58.675645 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-18 00:16:58.716709 | controller | ok 2025-12-18 00:16:58.733256 | controller | included: /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-18 00:16:58.750040 | 2025-12-18 00:16:58.750137 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-18 00:16:58.765703 | controller | skipping: Conditional result was False 2025-12-18 00:16:58.777177 | 2025-12-18 00:16:58.777350 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-18 00:16:59.064903 | controller | changed 2025-12-18 00:16:59.071601 | 2025-12-18 00:16:59.071745 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-18 00:16:59.300709 | controller | ok 2025-12-18 00:16:59.310056 | 2025-12-18 00:16:59.310285 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-18 00:16:59.933397 | controller | changed 2025-12-18 00:16:59.944012 | 2025-12-18 00:16:59.944125 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-18 00:17:00.565061 | controller | changed 2025-12-18 00:17:00.574822 | 2025-12-18 00:17:00.575022 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-18 00:17:00.604470 | controller | skipping: Conditional result was False 2025-12-18 00:17:00.612060 | 2025-12-18 00:17:00.612142 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-18 00:17:00.874330 | controller -> localhost | changed 2025-12-18 00:17:00.892510 | 2025-12-18 00:17:00.892631 | TASK [add-build-sshkey : Add back temp key] 2025-12-18 00:17:01.250059 | controller -> localhost | Identity added: /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/work/457ceca442de42219bf1d3d135050d61_id_ecdsa (zuul-build-sshkey) 2025-12-18 00:17:01.250210 | controller -> localhost | ok: Runtime: 0:00:00.011534 2025-12-18 00:17:01.256002 | 2025-12-18 00:17:01.256066 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-18 00:17:01.450048 | controller | ok 2025-12-18 00:17:01.456053 | 2025-12-18 00:17:01.456134 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-18 00:17:01.480614 | controller | skipping: Conditional result was False 2025-12-18 00:17:01.495452 | 2025-12-18 00:17:01.495565 | TASK [include_role : remove-zuul-sshkey] 2025-12-18 00:17:01.509840 | controller | skipping: Conditional result was False 2025-12-18 00:17:01.523245 | 2025-12-18 00:17:01.523362 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-18 00:17:01.751218 | controller | ok: "logs" 2025-12-18 00:17:01.751732 | controller | ok: All items complete 2025-12-18 00:17:01.751784 | 2025-12-18 00:17:01.955737 | controller | ok: "artifacts" 2025-12-18 00:17:02.157283 | controller | ok: "docs" 2025-12-18 00:17:02.182990 | 2025-12-18 00:17:02.183196 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-18 00:17:02.432069 | controller | changed: "logs" 2025-12-18 00:17:02.613781 | controller | changed: "artifacts" 2025-12-18 00:17:02.798239 | controller | changed: "docs" 2025-12-18 00:17:02.839373 | 2025-12-18 00:17:02.839474 | PLAY RECAP 2025-12-18 00:17:02.839515 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-18 00:17:02.839542 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-18 00:17:02.839561 | 2025-12-18 00:17:02.975939 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-18 00:17:02.977455 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-18 00:17:03.584962 | 2025-12-18 00:17:03.585182 | PLAY [all] 2025-12-18 00:17:03.607293 | 2025-12-18 00:17:03.607409 | TASK [Install binary dependencies] 2025-12-18 00:17:03.668327 | controller | ok 2025-12-18 00:17:03.690245 | 2025-12-18 00:17:03.690391 | TASK [bindep : Include find tasks] 2025-12-18 00:17:03.720579 | controller | ok 2025-12-18 00:17:03.729031 | controller | included: /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-18 00:17:03.735463 | 2025-12-18 00:17:03.735544 | TASK [bindep : Look for bindep.txt] 2025-12-18 00:17:04.097163 | controller | ok 2025-12-18 00:17:04.107937 | 2025-12-18 00:17:04.108058 | TASK [bindep : Define bindep_file fact] 2025-12-18 00:17:04.134191 | controller | skipping: Conditional result was False 2025-12-18 00:17:04.143522 | 2025-12-18 00:17:04.143638 | TASK [bindep : Look for other-requirements.txt] 2025-12-18 00:17:04.347795 | controller | ok 2025-12-18 00:17:04.353138 | 2025-12-18 00:17:04.353211 | TASK [bindep : Define bindep_file fact] 2025-12-18 00:17:04.389100 | controller | skipping: Conditional result was False 2025-12-18 00:17:04.404126 | 2025-12-18 00:17:04.404550 | TASK [bindep : Look for bindep fallback file] 2025-12-18 00:17:04.430907 | controller | skipping: Conditional result was False 2025-12-18 00:17:04.439237 | 2025-12-18 00:17:04.439344 | TASK [bindep : Define bindep_file fact] 2025-12-18 00:17:04.470305 | controller | skipping: Conditional result was False 2025-12-18 00:17:04.478766 | 2025-12-18 00:17:04.478877 | TASK [bindep : Include bindep tasks] 2025-12-18 00:17:04.514388 | controller | skipping: Conditional result was False 2025-12-18 00:17:04.523489 | 2025-12-18 00:17:04.523592 | TASK [bindep : Include install tasks] 2025-12-18 00:17:04.559314 | controller | skipping: Conditional result was False 2025-12-18 00:17:04.569080 | 2025-12-18 00:17:04.569191 | LOOP [bindep : Include package tasks] 2025-12-18 00:17:04.631028 | 2025-12-18 00:17:04.631235 | TASK [Run test-setup role] 2025-12-18 00:17:04.655799 | controller | ok 2025-12-18 00:17:04.681385 | 2025-12-18 00:17:04.681536 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-18 00:17:04.903581 | controller | ok 2025-12-18 00:17:04.917775 | 2025-12-18 00:17:04.918060 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-18 00:17:05.471557 | controller | skipping: Conditional result was False 2025-12-18 00:17:05.521208 | 2025-12-18 00:17:05.521399 | PLAY RECAP 2025-12-18 00:17:05.521463 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-18 00:17:05.521491 | 2025-12-18 00:17:05.627447 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-18 00:17:05.629375 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-18 00:17:06.225364 | 2025-12-18 00:17:06.225506 | PLAY [controller] 2025-12-18 00:17:06.245866 | 2025-12-18 00:17:06.245988 | TASK [Create the /root directory] 2025-12-18 00:17:06.640732 | controller | ok 2025-12-18 00:17:06.648472 | 2025-12-18 00:17:06.648605 | TASK [Install glibc-langpack-en] 2025-12-18 00:17:10.615911 | controller | ok: Nothing to do 2025-12-18 00:17:10.623850 | 2025-12-18 00:17:10.623959 | TASK [Ensure controller directory exists] 2025-12-18 00:17:10.851077 | controller | changed 2025-12-18 00:17:10.859412 | 2025-12-18 00:17:10.859501 | TASK [Install container runtime] 2025-12-18 00:17:10.902638 | controller | ok 2025-12-18 00:17:10.952481 | 2025-12-18 00:17:10.952615 | LOOP [ensure-podman : Find distribution installation] 2025-12-18 00:17:10.988339 | controller | ok: "/var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-18 00:17:11.007144 | controller | included: /var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-18 00:17:11.015478 | 2025-12-18 00:17:11.015580 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-18 00:18:15.221728 | controller | changed 2025-12-18 00:18:15.242783 | 2025-12-18 00:18:15.242934 | TASK [ensure-podman : Fetch podman version] 2025-12-18 00:18:15.865346 | controller | Client: Podman Engine 2025-12-18 00:18:15.895255 | controller | Version: 4.6.2 2025-12-18 00:18:15.895290 | controller | API Version: 4.6.2 2025-12-18 00:18:15.895298 | controller | Go Version: go1.19.12 2025-12-18 00:18:15.895315 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-18 00:18:15.895327 | controller | OS/Arch: linux/amd64 2025-12-18 00:18:16.306655 | controller | ok: Runtime: 0:00:00.181657 2025-12-18 00:18:16.313191 | 2025-12-18 00:18:16.313263 | TASK [ensure-podman : Print podman version installed] 2025-12-18 00:18:16.343383 | Podman version: Client: Podman Engine 2025-12-18 00:18:16.343606 | Version: 4.6.2 2025-12-18 00:18:16.343636 | API Version: 4.6.2 2025-12-18 00:18:16.343656 | Go Version: go1.19.12 2025-12-18 00:18:16.343704 | Built: Mon Aug 28 19:38:31 2023 2025-12-18 00:18:16.343726 | OS/Arch: linux/amd64 2025-12-18 00:18:16.349839 | 2025-12-18 00:18:16.349919 | TASK [ensure-podman : Validate podman engine] 2025-12-18 00:18:16.904958 | controller | skipping: Conditional result was False 2025-12-18 00:18:16.914129 | 2025-12-18 00:18:16.914260 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-18 00:18:16.938742 | controller | skipping: Conditional result was False 2025-12-18 00:18:16.953103 | 2025-12-18 00:18:16.953229 | TASK [Ensure python3.8 is present] 2025-12-18 00:18:16.967343 | controller | skipping: Conditional result was False 2025-12-18 00:18:16.975575 | 2025-12-18 00:18:16.975650 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-18 00:18:16.997339 | controller | ok 2025-12-18 00:18:17.026653 | 2025-12-18 00:18:17.026842 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-18 00:18:18.547899 | controller | ok: Nothing to do 2025-12-18 00:18:18.561075 | 2025-12-18 00:18:18.561190 | TASK [our-ensure-python : Also install python3-devel] 2025-12-18 00:18:27.898521 | controller | changed 2025-12-18 00:18:27.920190 | 2025-12-18 00:18:27.920351 | TASK [Run ensure-virtualenv role] 2025-12-18 00:18:27.941689 | controller | ok 2025-12-18 00:18:27.966212 | 2025-12-18 00:18:27.966341 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-18 00:18:28.177759 | controller | /usr/bin/virtualenv 2025-12-18 00:18:28.498599 | controller | ok: Runtime: 0:00:00.004929 2025-12-18 00:18:28.511999 | 2025-12-18 00:18:28.512244 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-18 00:18:28.536936 | controller | skipping: Conditional result was False 2025-12-18 00:18:28.537315 | controller | ok: All items complete 2025-12-18 00:18:28.537355 | 2025-12-18 00:18:28.564992 | 2025-12-18 00:18:28.565273 | TASK [Find the full path of the Python interpreter] 2025-12-18 00:18:28.884299 | controller | /usr/bin/python3 2025-12-18 00:18:29.182822 | controller | ok 2025-12-18 00:18:29.196187 | 2025-12-18 00:18:29.196362 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-18 00:18:30.079956 | controller | created virtual environment CPython3.11.0.final.0-64 in 455ms 2025-12-18 00:18:30.102082 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-18 00:18:30.102639 | 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/.local/share/virtualenv) 2025-12-18 00:18:30.102652 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-18 00:18:30.102666 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-18 00:18:30.258611 | controller | changed 2025-12-18 00:18:30.268425 | 2025-12-18 00:18:30.268808 | TASK [Set selinux package] 2025-12-18 00:18:30.303674 | controller | ok 2025-12-18 00:18:30.309743 | 2025-12-18 00:18:30.309814 | TASK [Set selinux package (Fedora)] 2025-12-18 00:18:30.371000 | controller | ok 2025-12-18 00:18:30.387636 | 2025-12-18 00:18:30.387864 | TASK [Install selinux into virtualenv] 2025-12-18 00:18:56.002133 | controller | Collecting selinux-please-lie-to-me 2025-12-18 00:19:08.261882 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-18 00:19:08.621749 | controller | Collecting setuptools<50.0.0 2025-12-18 00:19:08.626972 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-18 00:19:08.678318 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 17.8 MB/s eta 0:00:00 2025-12-18 00:19:08.761059 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-18 00:19:08.761292 | controller | Attempting uninstall: setuptools 2025-12-18 00:19:08.763700 | controller | Found existing installation: setuptools 62.6.0 2025-12-18 00:19:08.822433 | controller | Uninstalling setuptools-62.6.0: 2025-12-18 00:19:08.830541 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-18 00:19:09.180622 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-18 00:19:22.576840 | controller | 2025-12-18 00:19:22.668448 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-18 00:19:22.668489 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-18 00:19:22.989989 | controller | ok: Runtime: 0:00:51.973821 2025-12-18 00:19:22.996716 | 2025-12-18 00:19:22.996787 | TASK [Install pytest-forked into virtualenv] 2025-12-18 00:19:42.985225 | controller | Collecting pytest-forked 2025-12-18 00:19:55.236112 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-18 00:19:55.282367 | controller | Collecting py 2025-12-18 00:19:55.286472 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-18 00:19:55.306338 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.4 MB/s eta 0:00:00 2025-12-18 00:19:55.423096 | controller | Collecting pytest>=3.10 2025-12-18 00:19:55.431551 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-18 00:19:55.450123 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 24.4 MB/s eta 0:00:00 2025-12-18 00:19:55.489365 | controller | Collecting iniconfig>=1.0.1 2025-12-18 00:19:55.493287 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-18 00:19:55.537808 | controller | Collecting packaging>=22 2025-12-18 00:19:55.541739 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-18 00:19:55.547216 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 17.1 MB/s eta 0:00:00 2025-12-18 00:19:55.584707 | controller | Collecting pluggy<2,>=1.5 2025-12-18 00:19:55.588116 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-18 00:19:55.632778 | controller | Collecting pygments>=2.7.2 2025-12-18 00:19:55.635879 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-18 00:19:55.661313 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 61.4 MB/s eta 0:00:00 2025-12-18 00:19:55.732104 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-18 00:19:56.789604 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0 2025-12-18 00:19:56.798223 | controller | 2025-12-18 00:19:56.864636 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-18 00:19:56.864669 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-18 00:19:57.048432 | controller | ok: Runtime: 0:00:33.672072 2025-12-18 00:19:57.056541 | 2025-12-18 00:19:57.056659 | TASK [Update pip] 2025-12-18 00:19:57.560633 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-18 00:20:19.588071 | controller | Collecting pip 2025-12-18 00:20:31.782705 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-18 00:20:31.852847 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 28.0 MB/s eta 0:00:00 2025-12-18 00:20:31.927006 | controller | Installing collected packages: pip 2025-12-18 00:20:31.927164 | controller | Attempting uninstall: pip 2025-12-18 00:20:31.929411 | controller | Found existing installation: pip 22.2.2 2025-12-18 00:20:32.070300 | controller | Uninstalling pip-22.2.2: 2025-12-18 00:20:32.089711 | controller | Successfully uninstalled pip-22.2.2 2025-12-18 00:20:32.915202 | controller | Successfully installed pip-25.3 2025-12-18 00:20:33.118119 | controller | ok: Runtime: 0:00:35.726862 2025-12-18 00:20:33.135403 | 2025-12-18 00:20:33.135655 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-18 00:20:33.378185 | controller | changed 2025-12-18 00:20:33.392931 | 2025-12-18 00:20:33.393102 | TASK [Install ansible into virtualenv] 2025-12-18 00:20:33.947835 | controller | Processing ./src/github.com/ansible/ansible 2025-12-18 00:20:33.951379 | controller | Installing build dependencies: started 2025-12-18 00:21:20.889634 | controller | Installing build dependencies: finished with status 'done' 2025-12-18 00:21:20.890780 | controller | Getting requirements to build wheel: started 2025-12-18 00:21:21.639549 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-18 00:21:21.640477 | controller | Preparing metadata (pyproject.toml): started 2025-12-18 00:21:22.100161 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-18 00:21:22.105564 | 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-12-18 00:21:22.109416 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-18 00:21:22.469924 | controller | ERROR 2025-12-18 00:21:22.470112 | controller | { 2025-12-18 00:21:22.470150 | controller | "delta": "0:00:48.548434", 2025-12-18 00:21:22.470176 | controller | "end": "2025-12-18 00:21:22.184264", 2025-12-18 00:21:22.470200 | controller | "msg": "non-zero return code", 2025-12-18 00:21:22.470235 | controller | "rc": 1, 2025-12-18 00:21:22.470259 | controller | "start": "2025-12-18 00:20:33.635830" 2025-12-18 00:21:22.470281 | controller | } failure 2025-12-18 00:21:22.472328 | 2025-12-18 00:21:22.472385 | PLAY RECAP 2025-12-18 00:21:22.472436 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-18 00:21:22.472464 | 2025-12-18 00:21:22.639090 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-18 00:21:22.640380 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-18 00:21:23.249258 | 2025-12-18 00:21:23.249393 | PLAY [all] 2025-12-18 00:21:23.276192 | 2025-12-18 00:21:23.276333 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-18 00:21:23.520404 | controller | changed: non-zero return code 2025-12-18 00:21:23.526098 | 2025-12-18 00:21:23.526171 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-18 00:21:23.545382 | controller | skipping: Conditional result was False 2025-12-18 00:21:23.551721 | 2025-12-18 00:21:23.551799 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-18 00:21:23.582843 | 2025-12-18 00:21:23.583006 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-18 00:21:23.613778 | 2025-12-18 00:21:23.613934 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-18 00:21:23.638596 | controller | skipping: Conditional result was False 2025-12-18 00:21:23.646080 | 2025-12-18 00:21:23.646155 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-18 00:21:23.684077 | 2025-12-18 00:21:23.684354 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-18 00:21:23.701195 | controller | skipping: Conditional result was False 2025-12-18 00:21:23.711151 | 2025-12-18 00:21:23.711274 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-18 00:21:23.727546 | controller | skipping: Conditional result was False 2025-12-18 00:21:23.737461 | 2025-12-18 00:21:23.737558 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-18 00:21:23.753716 | controller | skipping: Conditional result was False 2025-12-18 00:21:23.794866 | 2025-12-18 00:21:23.794989 | PLAY RECAP 2025-12-18 00:21:23.795039 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-18 00:21:23.795060 | 2025-12-18 00:21:23.893966 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-18 00:21:23.894862 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-18 00:21:24.590895 | 2025-12-18 00:21:24.591041 | PLAY [all:!appliance*] 2025-12-18 00:21:24.615267 | 2025-12-18 00:21:24.615358 | TASK [unregister the node] 2025-12-18 00:21:25.147917 | controller | skipping: Conditional result was False 2025-12-18 00:21:25.154648 | 2025-12-18 00:21:25.154807 | TASK [include_role : fetch-output] 2025-12-18 00:21:25.189867 | controller | ok 2025-12-18 00:21:25.217814 | 2025-12-18 00:21:25.217974 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-18 00:21:25.295574 | controller | skipping: Conditional result was False 2025-12-18 00:21:25.304983 | 2025-12-18 00:21:25.305138 | TASK [fetch-output : Set log path for single node] 2025-12-18 00:21:25.349631 | controller | ok 2025-12-18 00:21:25.357288 | 2025-12-18 00:21:25.357411 | LOOP [fetch-output : Ensure local output dirs] 2025-12-18 00:21:25.796396 | controller -> localhost | ok: "/var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/work/logs" 2025-12-18 00:21:26.069103 | controller -> localhost | changed: "/var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/work/artifacts" 2025-12-18 00:21:26.352780 | controller -> localhost | changed: "/var/lib/zuul/builds/457ceca442de42219bf1d3d135050d61/work/docs" 2025-12-18 00:21:26.373592 | 2025-12-18 00:21:26.376625 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-18 00:21:27.143657 | controller | changed: 2025-12-18 00:21:27.144098 | controller | .d..t...... ./ 2025-12-18 00:21:27.144152 | controller | cd+++++++++ controller/ 2025-12-18 00:21:27.144203 | controller | changed: All items complete 2025-12-18 00:21:27.144234 | 2025-12-18 00:21:27.641059 | controller | changed: .d..t...... ./ 2025-12-18 00:21:28.182874 | controller | changed: .d..t...... ./ 2025-12-18 00:21:28.215328 | 2025-12-18 00:21:28.215472 | TASK [include_role : fetch-output-openshift] 2025-12-18 00:21:28.242025 | controller | skipping: Conditional result was False 2025-12-18 00:21:28.252508 | 2025-12-18 00:21:28.252635 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-18 00:21:28.298936 | controller | skipping: Conditional result was False 2025-12-18 00:21:28.311211 | controller | skipping: Conditional result was False 2025-12-18 00:21:28.357764 | 2025-12-18 00:21:28.357959 | PLAY [localhost] 2025-12-18 00:21:28.373773 | 2025-12-18 00:21:28.373882 | TASK [Run Zuul manifest role] 2025-12-18 00:21:28.406510 | localhost | ok 2025-12-18 00:21:28.435034 | 2025-12-18 00:21:28.435166 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-18 00:21:28.945454 | localhost | changed 2025-12-18 00:21:28.951291 | 2025-12-18 00:21:28.951417 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-18 00:21:28.993616 | localhost | ok 2025-12-18 00:21:29.005762 | 2025-12-18 00:21:29.005856 | TASK [Set zuul-log-path fact] 2025-12-18 00:21:29.027031 | localhost | ok 2025-12-18 00:21:29.045930 | 2025-12-18 00:21:29.046044 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-18 00:21:29.087748 | localhost | ok 2025-12-18 00:21:29.104275 | 2025-12-18 00:21:29.104489 | LOOP [Run upload-logs-swift role] 2025-12-18 00:21:29.130964 | localhost | Output suppressed because no_log was given 2025-12-18 00:21:29.176784 | 2025-12-18 00:21:29.176971 | TASK [Set zuul-log-path fact] 2025-12-18 00:21:29.202793 | localhost | skipping: Conditional result was False 2025-12-18 00:21:29.208449 | 2025-12-18 00:21:29.208534 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-18 00:21:29.681660 | localhost -> localhost | ok: Runtime: 0:00:00.006463 2025-12-18 00:21:29.736522 | 2025-12-18 00:21:29.736727 | TASK [upload-logs-swift : Upload logs to swift]