2025-10-05 00:06:33.747909 | Job console starting... 2025-10-05 00:06:33.758949 | Updating repositories 2025-10-05 00:06:33.860556 | Preparing job workspace 2025-10-05 00:06:37.656318 | Running Ansible setup... 2025-10-05 00:06:43.123598 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-05 00:06:43.746940 | 2025-10-05 00:06:43.747058 | PLAY [localhost] 2025-10-05 00:06:43.755683 | 2025-10-05 00:06:43.755792 | TASK [Gathering Facts] 2025-10-05 00:06:44.784330 | localhost | ok 2025-10-05 00:06:44.800344 | 2025-10-05 00:06:44.800510 | TASK [Setup log path fact] 2025-10-05 00:06:44.831166 | localhost | ok 2025-10-05 00:06:44.857815 | 2025-10-05 00:06:44.857959 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-05 00:06:44.887902 | localhost | ok 2025-10-05 00:06:44.898983 | 2025-10-05 00:06:44.899117 | TASK [emit-job-header : Print job information] 2025-10-05 00:06:44.950299 | # Job Information 2025-10-05 00:06:44.950475 | Ansible Version: 2.15.12 2025-10-05 00:06:44.950530 | Job: ansible-test-sanity-docker-milestone 2025-10-05 00:06:44.950567 | Pipeline: periodic 2025-10-05 00:06:44.950601 | Executor: ze03.softwarefactory-project.io 2025-10-05 00:06:44.950635 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-05 00:06:44.950672 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/f2c/ansible/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/ 2025-10-05 00:06:44.950705 | Event ID: 82198ffb092345eeb6b1fdd59cdb0848 2025-10-05 00:06:44.955314 | 2025-10-05 00:06:44.955414 | LOOP [emit-job-header : Print node information] 2025-10-05 00:06:45.052985 | localhost | ok: 2025-10-05 00:06:45.053202 | localhost | # Node Information 2025-10-05 00:06:45.053231 | localhost | Inventory Hostname: controller 2025-10-05 00:06:45.053252 | localhost | Hostname: ip-172-16-135-248 2025-10-05 00:06:45.053272 | localhost | Username: zuul-worker 2025-10-05 00:06:45.053292 | localhost | Distro: Fedora 37 2025-10-05 00:06:45.053312 | localhost | Provider: ansible-us-east-2 2025-10-05 00:06:45.053330 | localhost | Region: us-east-2 2025-10-05 00:06:45.053349 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-05 00:06:45.053366 | localhost | Product Name: t3.small 2025-10-05 00:06:45.053384 | localhost | Interface IP: 18.191.73.91 2025-10-05 00:06:45.074210 | 2025-10-05 00:06:45.074357 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-05 00:06:45.447890 | localhost -> localhost | changed 2025-10-05 00:06:45.454120 | 2025-10-05 00:06:45.454200 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-05 00:06:46.383228 | localhost -> localhost | changed 2025-10-05 00:06:46.423845 | 2025-10-05 00:06:46.424067 | PLAY [all:!appliance*] 2025-10-05 00:06:46.444922 | 2025-10-05 00:06:46.445108 | TASK [include_role : start-zuul-console] 2025-10-05 00:06:46.465330 | controller | ok 2025-10-05 00:06:46.479170 | 2025-10-05 00:06:46.479262 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-05 00:06:47.162346 | controller | ok 2025-10-05 00:06:47.186338 | 2025-10-05 00:06:47.186596 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-05 00:06:48.528712 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-05 00:06:48.540343 | 2025-10-05 00:06:48.540537 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-05 00:06:48.685673 | controller | skipping: Conditional result was False 2025-10-05 00:06:48.699107 | 2025-10-05 00:06:48.699284 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-05 00:06:48.725806 | controller | skipping: Conditional result was False 2025-10-05 00:06:48.734344 | 2025-10-05 00:06:48.734477 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-05 00:06:48.770701 | controller | skipping: Conditional result was False 2025-10-05 00:06:48.779117 | 2025-10-05 00:06:48.779219 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-05 00:06:48.803306 | controller | skipping: Conditional result was False 2025-10-05 00:06:48.810128 | 2025-10-05 00:06:48.810234 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-05 00:06:48.835133 | controller | skipping: Conditional result was False 2025-10-05 00:06:48.843541 | 2025-10-05 00:06:48.843669 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-05 00:06:48.868558 | controller | skipping: Conditional result was False 2025-10-05 00:06:48.881660 | 2025-10-05 00:06:48.881838 | TASK [Disable Fedora Modular] 2025-10-05 00:06:49.604716 | controller | changed 2025-10-05 00:06:49.615507 | 2025-10-05 00:06:49.615694 | TASK [Enable EPEL] 2025-10-05 00:06:49.643013 | controller | skipping: Conditional result was False 2025-10-05 00:06:49.653985 | 2025-10-05 00:06:49.654195 | TASK [Register the RHEL node] 2025-10-05 00:06:49.820594 | 2025-10-05 00:06:49.820870 | TASK [Show the subscription-manager status] 2025-10-05 00:06:49.962639 | controller | skipping: Conditional result was False 2025-10-05 00:06:49.975696 | 2025-10-05 00:06:49.975885 | TASK [Enable EPEL on RHEL] 2025-10-05 00:06:50.161347 | controller | skipping: Conditional result was False 2025-10-05 00:06:50.167912 | 2025-10-05 00:06:50.168017 | TASK [Install git and tox] 2025-10-05 00:08:19.642905 | controller | changed 2025-10-05 00:08:19.651105 | 2025-10-05 00:08:19.651398 | TASK [include_role : prepare-workspace] 2025-10-05 00:08:19.672243 | controller | ok 2025-10-05 00:08:19.694963 | 2025-10-05 00:08:19.695083 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-05 00:08:20.261130 | controller | ok 2025-10-05 00:08:20.274099 | 2025-10-05 00:08:20.274187 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-05 00:08:33.720418 | controller | Output suppressed because no_log was given 2025-10-05 00:08:33.750657 | 2025-10-05 00:08:33.750866 | TASK [include_role : prepare-workspace-openshift] 2025-10-05 00:08:33.776377 | controller | skipping: Conditional result was False 2025-10-05 00:08:33.802300 | 2025-10-05 00:08:33.802419 | PLAY [all:!appliance] 2025-10-05 00:08:33.864040 | 2025-10-05 00:08:33.864184 | TASK [Run add-build-sshkey role (RSA)] 2025-10-05 00:08:33.888134 | controller | ok 2025-10-05 00:08:33.911862 | 2025-10-05 00:08:33.912052 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-05 00:08:34.184176 | controller -> localhost | ok 2025-10-05 00:08:34.190865 | 2025-10-05 00:08:34.191026 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-05 00:08:34.226048 | controller | ok 2025-10-05 00:08:34.246897 | controller | included: /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-05 00:08:34.254151 | 2025-10-05 00:08:34.254284 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-05 00:08:34.870703 | controller -> localhost | Generating public/private rsa key pair. 2025-10-05 00:08:34.870946 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/work/f2c2aedfe9ba4088b3f0b51dd8ea0ca6_id_rsa. 2025-10-05 00:08:34.870976 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/work/f2c2aedfe9ba4088b3f0b51dd8ea0ca6_id_rsa.pub. 2025-10-05 00:08:34.870996 | controller -> localhost | The key fingerprint is: 2025-10-05 00:08:34.871015 | controller -> localhost | SHA256:nmkHtzCIOZnp01EOnc9PhBfzCEL9vA/v5VEZTBvV1Bc zuul-build-sshkey 2025-10-05 00:08:34.871037 | controller -> localhost | The key's randomart image is: 2025-10-05 00:08:34.871057 | controller -> localhost | +---[RSA 2048]----+ 2025-10-05 00:08:34.871075 | controller -> localhost | | .o.. o EB| 2025-10-05 00:08:34.871096 | controller -> localhost | | . o.o =o *| 2025-10-05 00:08:34.871115 | controller -> localhost | | . + .o+ .+.| 2025-10-05 00:08:34.871133 | controller -> localhost | | * = o oo o| 2025-10-05 00:08:34.871151 | controller -> localhost | | B o S + .. ..| 2025-10-05 00:08:34.871178 | controller -> localhost | | . o o B +o .| 2025-10-05 00:08:34.871202 | controller -> localhost | | o . = o .+ ..| 2025-10-05 00:08:34.871222 | controller -> localhost | | . . . oo.| 2025-10-05 00:08:34.871239 | controller -> localhost | | .. .| 2025-10-05 00:08:34.871259 | controller -> localhost | +----[SHA256]-----+ 2025-10-05 00:08:34.871310 | controller -> localhost | ok: Runtime: 0:00:00.195201 2025-10-05 00:08:34.878146 | 2025-10-05 00:08:34.878231 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-05 00:08:34.911299 | controller | ok 2025-10-05 00:08:34.928255 | controller | included: /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-05 00:08:34.954508 | 2025-10-05 00:08:34.954793 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-05 00:08:34.986431 | controller | skipping: Conditional result was False 2025-10-05 00:08:34.994766 | 2025-10-05 00:08:34.994903 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-05 00:08:35.707881 | controller | changed 2025-10-05 00:08:35.715941 | 2025-10-05 00:08:35.716123 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-05 00:08:36.044687 | controller | ok 2025-10-05 00:08:36.058324 | 2025-10-05 00:08:36.058487 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-05 00:08:37.320391 | controller | changed 2025-10-05 00:08:37.326634 | 2025-10-05 00:08:37.326788 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-05 00:08:38.569568 | controller | changed 2025-10-05 00:08:38.578680 | 2025-10-05 00:08:38.578844 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-05 00:08:38.605863 | controller | skipping: Conditional result was False 2025-10-05 00:08:38.615520 | 2025-10-05 00:08:38.615668 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-05 00:08:39.029876 | controller -> localhost | changed 2025-10-05 00:08:39.047215 | 2025-10-05 00:08:39.047355 | TASK [add-build-sshkey : Add back temp key] 2025-10-05 00:08:39.390273 | controller -> localhost | Identity added: /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/work/f2c2aedfe9ba4088b3f0b51dd8ea0ca6_id_rsa (zuul-build-sshkey) 2025-10-05 00:08:39.390751 | controller -> localhost | ok: Runtime: 0:00:00.014249 2025-10-05 00:08:39.405181 | 2025-10-05 00:08:39.405391 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-05 00:08:39.969453 | controller | ok 2025-10-05 00:08:39.975074 | 2025-10-05 00:08:39.975171 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-05 00:08:40.012868 | controller | skipping: Conditional result was False 2025-10-05 00:08:40.025388 | 2025-10-05 00:08:40.025524 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-05 00:08:40.046442 | controller | ok 2025-10-05 00:08:40.063603 | 2025-10-05 00:08:40.063753 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-05 00:08:40.294824 | controller -> localhost | ok 2025-10-05 00:08:40.302496 | 2025-10-05 00:08:40.302656 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-05 00:08:40.336033 | controller | ok 2025-10-05 00:08:40.350544 | controller | included: /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-05 00:08:40.358284 | 2025-10-05 00:08:40.358418 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-05 00:08:40.629795 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-05 00:08:40.630032 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/work/f2c2aedfe9ba4088b3f0b51dd8ea0ca6_id_ecdsa. 2025-10-05 00:08:40.630062 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/work/f2c2aedfe9ba4088b3f0b51dd8ea0ca6_id_ecdsa.pub. 2025-10-05 00:08:40.630095 | controller -> localhost | The key fingerprint is: 2025-10-05 00:08:40.630116 | controller -> localhost | SHA256:zv5JOtfVGzxspBPb+7hjU4z0xUHSX26+yGtTNeW6TmE zuul-build-sshkey 2025-10-05 00:08:40.630135 | controller -> localhost | The key's randomart image is: 2025-10-05 00:08:40.630154 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-05 00:08:40.630172 | controller -> localhost | | .o. | 2025-10-05 00:08:40.630190 | controller -> localhost | | .oo| 2025-10-05 00:08:40.630207 | controller -> localhost | | +=| 2025-10-05 00:08:40.630225 | controller -> localhost | | ..oO| 2025-10-05 00:08:40.630243 | controller -> localhost | | S .EO+| 2025-10-05 00:08:40.630260 | controller -> localhost | | o =+X*| 2025-10-05 00:08:40.630277 | controller -> localhost | | o ....*o*| 2025-10-05 00:08:40.630294 | controller -> localhost | | ..o...*== | 2025-10-05 00:08:40.630311 | controller -> localhost | | o+o .+*+o| 2025-10-05 00:08:40.630328 | controller -> localhost | +----[SHA256]-----+ 2025-10-05 00:08:40.630373 | controller -> localhost | ok: Runtime: 0:00:00.016579 2025-10-05 00:08:40.638557 | 2025-10-05 00:08:40.638707 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-05 00:08:40.659960 | controller | ok 2025-10-05 00:08:40.669007 | controller | included: /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-05 00:08:40.679169 | 2025-10-05 00:08:40.679338 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-05 00:08:40.694650 | controller | skipping: Conditional result was False 2025-10-05 00:08:40.702541 | 2025-10-05 00:08:40.702817 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-05 00:08:41.145059 | controller | changed 2025-10-05 00:08:41.151471 | 2025-10-05 00:08:41.151607 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-05 00:08:41.485280 | controller | ok 2025-10-05 00:08:41.493446 | 2025-10-05 00:08:41.493545 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-05 00:08:42.825714 | controller | changed 2025-10-05 00:08:42.835397 | 2025-10-05 00:08:42.835558 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-05 00:08:44.103426 | controller | changed 2025-10-05 00:08:44.112425 | 2025-10-05 00:08:44.112545 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-05 00:08:44.149574 | controller | skipping: Conditional result was False 2025-10-05 00:08:44.157138 | 2025-10-05 00:08:44.157235 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-05 00:08:44.437127 | controller -> localhost | changed 2025-10-05 00:08:44.451343 | 2025-10-05 00:08:44.451481 | TASK [add-build-sshkey : Add back temp key] 2025-10-05 00:08:44.741611 | controller -> localhost | Identity added: /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/work/f2c2aedfe9ba4088b3f0b51dd8ea0ca6_id_ecdsa (zuul-build-sshkey) 2025-10-05 00:08:44.741838 | controller -> localhost | ok: Runtime: 0:00:00.010631 2025-10-05 00:08:44.748373 | 2025-10-05 00:08:44.748465 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-05 00:08:45.058768 | controller | ok 2025-10-05 00:08:45.067725 | 2025-10-05 00:08:45.067899 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-05 00:08:45.105913 | controller | skipping: Conditional result was False 2025-10-05 00:08:45.160962 | 2025-10-05 00:08:45.161091 | TASK [include_role : remove-zuul-sshkey] 2025-10-05 00:08:45.176064 | controller | skipping: Conditional result was False 2025-10-05 00:08:45.185151 | 2025-10-05 00:08:45.185280 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-05 00:08:45.517316 | controller | ok: "logs" 2025-10-05 00:08:45.517835 | controller | ok: All items complete 2025-10-05 00:08:45.517885 | 2025-10-05 00:08:46.031334 | controller | ok: "artifacts" 2025-10-05 00:08:46.302766 | controller | ok: "docs" 2025-10-05 00:08:46.331837 | 2025-10-05 00:08:46.332045 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-05 00:08:46.649025 | controller | changed: "logs" 2025-10-05 00:08:46.920137 | controller | changed: "artifacts" 2025-10-05 00:08:47.209997 | controller | changed: "docs" 2025-10-05 00:08:47.255878 | 2025-10-05 00:08:47.256284 | PLAY RECAP 2025-10-05 00:08:47.256495 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-05 00:08:47.256551 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-05 00:08:47.256582 | 2025-10-05 00:08:47.413974 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-05 00:08:47.414829 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-05 00:08:48.038327 | 2025-10-05 00:08:48.038473 | PLAY [all] 2025-10-05 00:08:48.080677 | 2025-10-05 00:08:48.080883 | TASK [Install binary dependencies] 2025-10-05 00:08:48.132120 | controller | ok 2025-10-05 00:08:48.154213 | 2025-10-05 00:08:48.154373 | TASK [bindep : Include find tasks] 2025-10-05 00:08:48.184529 | controller | ok 2025-10-05 00:08:48.194600 | controller | included: /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-05 00:08:48.201684 | 2025-10-05 00:08:48.201838 | TASK [bindep : Look for bindep.txt] 2025-10-05 00:08:48.763935 | controller | ok 2025-10-05 00:08:48.770670 | 2025-10-05 00:08:48.770777 | TASK [bindep : Define bindep_file fact] 2025-10-05 00:08:48.797053 | controller | skipping: Conditional result was False 2025-10-05 00:08:48.804096 | 2025-10-05 00:08:48.804186 | TASK [bindep : Look for other-requirements.txt] 2025-10-05 00:08:49.147440 | controller | ok 2025-10-05 00:08:49.155999 | 2025-10-05 00:08:49.156140 | TASK [bindep : Define bindep_file fact] 2025-10-05 00:08:49.182324 | controller | skipping: Conditional result was False 2025-10-05 00:08:49.192387 | 2025-10-05 00:08:49.192575 | TASK [bindep : Look for bindep fallback file] 2025-10-05 00:08:49.218450 | controller | skipping: Conditional result was False 2025-10-05 00:08:49.228343 | 2025-10-05 00:08:49.228477 | TASK [bindep : Define bindep_file fact] 2025-10-05 00:08:49.254415 | controller | skipping: Conditional result was False 2025-10-05 00:08:49.260730 | 2025-10-05 00:08:49.260831 | TASK [bindep : Include bindep tasks] 2025-10-05 00:08:49.285208 | controller | skipping: Conditional result was False 2025-10-05 00:08:49.296424 | 2025-10-05 00:08:49.296585 | TASK [bindep : Include install tasks] 2025-10-05 00:08:49.329005 | controller | skipping: Conditional result was False 2025-10-05 00:08:49.335364 | 2025-10-05 00:08:49.335460 | LOOP [bindep : Include package tasks] 2025-10-05 00:08:49.398042 | 2025-10-05 00:08:49.398226 | TASK [Run test-setup role] 2025-10-05 00:08:49.419919 | controller | ok 2025-10-05 00:08:49.440387 | 2025-10-05 00:08:49.440528 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-05 00:08:49.758284 | controller | ok 2025-10-05 00:08:49.764984 | 2025-10-05 00:08:49.765049 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-05 00:08:49.899270 | controller | skipping: Conditional result was False 2025-10-05 00:08:49.940256 | 2025-10-05 00:08:49.940369 | PLAY RECAP 2025-10-05 00:08:49.940413 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-05 00:08:49.940436 | 2025-10-05 00:08:50.057589 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-05 00:08:50.058708 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-05 00:08:50.749786 | 2025-10-05 00:08:50.749964 | PLAY [controller] 2025-10-05 00:08:50.771354 | 2025-10-05 00:08:50.771501 | TASK [Create the /root directory] 2025-10-05 00:08:51.511882 | controller | ok 2025-10-05 00:08:51.517929 | 2025-10-05 00:08:51.518007 | TASK [Install glibc-langpack-en] 2025-10-05 00:08:59.535632 | controller | ok: Nothing to do 2025-10-05 00:08:59.549135 | 2025-10-05 00:08:59.549314 | TASK [Ensure controller directory exists] 2025-10-05 00:09:00.055192 | controller | changed 2025-10-05 00:09:00.061097 | 2025-10-05 00:09:00.061186 | TASK [Install container runtime] 2025-10-05 00:09:00.105141 | controller | ok 2025-10-05 00:09:00.142415 | 2025-10-05 00:09:00.142547 | LOOP [ensure-podman : Find distribution installation] 2025-10-05 00:09:00.170172 | controller | ok: "/var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-05 00:09:00.186546 | controller | included: /var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-05 00:09:00.195862 | 2025-10-05 00:09:00.196004 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-05 00:10:17.362433 | controller | changed 2025-10-05 00:10:17.369284 | 2025-10-05 00:10:17.369407 | TASK [ensure-podman : Fetch podman version] 2025-10-05 00:10:18.089652 | controller | Client: Podman Engine 2025-10-05 00:10:18.116086 | controller | Version: 4.6.2 2025-10-05 00:10:18.116136 | controller | API Version: 4.6.2 2025-10-05 00:10:18.116146 | controller | Go Version: go1.19.12 2025-10-05 00:10:18.116166 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-05 00:10:18.116176 | controller | OS/Arch: linux/amd64 2025-10-05 00:10:18.504784 | controller | ok: Runtime: 0:00:00.193939 2025-10-05 00:10:18.513208 | 2025-10-05 00:10:18.513311 | TASK [ensure-podman : Print podman version installed] 2025-10-05 00:10:18.556181 | Podman version: Client: Podman Engine 2025-10-05 00:10:18.556382 | Version: 4.6.2 2025-10-05 00:10:18.556421 | API Version: 4.6.2 2025-10-05 00:10:18.556452 | Go Version: go1.19.12 2025-10-05 00:10:18.556479 | Built: Mon Aug 28 19:38:31 2023 2025-10-05 00:10:18.556508 | OS/Arch: linux/amd64 2025-10-05 00:10:18.563840 | 2025-10-05 00:10:18.563933 | TASK [ensure-podman : Validate podman engine] 2025-10-05 00:10:18.704042 | controller | skipping: Conditional result was False 2025-10-05 00:10:18.717769 | 2025-10-05 00:10:18.717946 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-05 00:10:18.734942 | controller | skipping: Conditional result was False 2025-10-05 00:10:18.762078 | 2025-10-05 00:10:18.762337 | TASK [Ensure python3.8 is present] 2025-10-05 00:10:18.787279 | controller | skipping: Conditional result was False 2025-10-05 00:10:18.796893 | 2025-10-05 00:10:18.797007 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-05 00:10:18.829914 | controller | ok 2025-10-05 00:10:18.858955 | 2025-10-05 00:10:18.859113 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-05 00:10:22.577915 | controller | ok: Nothing to do 2025-10-05 00:10:22.590421 | 2025-10-05 00:10:22.590675 | TASK [our-ensure-python : Also install python3-devel] 2025-10-05 00:10:35.741089 | controller | changed 2025-10-05 00:10:35.766584 | 2025-10-05 00:10:35.766770 | TASK [Run ensure-virtualenv role] 2025-10-05 00:10:35.795947 | controller | ok 2025-10-05 00:10:35.834170 | 2025-10-05 00:10:35.834324 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-05 00:10:36.212325 | controller | /usr/bin/virtualenv 2025-10-05 00:10:36.475821 | controller | ok: Runtime: 0:00:00.004508 2025-10-05 00:10:36.481982 | 2025-10-05 00:10:36.482114 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-05 00:10:36.500873 | controller | skipping: Conditional result was False 2025-10-05 00:10:36.501140 | controller | ok: All items complete 2025-10-05 00:10:36.501169 | 2025-10-05 00:10:36.518393 | 2025-10-05 00:10:36.518564 | TASK [Find the full path of the Python interpreter] 2025-10-05 00:10:36.959734 | controller | /usr/bin/python3 2025-10-05 00:10:37.191420 | controller | ok 2025-10-05 00:10:37.204117 | 2025-10-05 00:10:37.204313 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-05 00:10:38.664199 | controller | created virtual environment CPython3.11.0.final.0-64 in 788ms 2025-10-05 00:10:38.705160 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-05 00:10:38.705219 | 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-05 00:10:38.705237 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-05 00:10:38.705261 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-05 00:10:38.867939 | controller | changed 2025-10-05 00:10:38.876181 | 2025-10-05 00:10:38.876276 | TASK [Set selinux package] 2025-10-05 00:10:38.908337 | controller | ok 2025-10-05 00:10:38.919416 | 2025-10-05 00:10:38.919499 | TASK [Set selinux package (Fedora)] 2025-10-05 00:10:38.952991 | controller | ok 2025-10-05 00:10:38.977005 | 2025-10-05 00:10:38.977140 | TASK [Install selinux into virtualenv] 2025-10-05 00:10:41.541188 | controller | Collecting selinux-please-lie-to-me 2025-10-05 00:10:41.630495 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-05 00:10:42.158447 | controller | Collecting setuptools<50.0.0 2025-10-05 00:10:42.176268 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-05 00:10:42.272579 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 8.8 MB/s eta 0:00:00 2025-10-05 00:10:42.456947 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-05 00:10:42.457358 | controller | Attempting uninstall: setuptools 2025-10-05 00:10:42.462195 | controller | Found existing installation: setuptools 62.6.0 2025-10-05 00:10:42.573899 | controller | Uninstalling setuptools-62.6.0: 2025-10-05 00:10:42.589163 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-05 00:10:43.336247 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-05 00:10:43.545286 | controller | 2025-10-05 00:10:43.755255 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-05 00:10:43.755307 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-05 00:10:44.154790 | controller | ok: Runtime: 0:00:04.317708 2025-10-05 00:10:44.162561 | 2025-10-05 00:10:44.162705 | TASK [Install pytest-forked into virtualenv] 2025-10-05 00:10:45.353959 | controller | Collecting pytest-forked 2025-10-05 00:10:45.439140 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-05 00:10:45.496855 | controller | Collecting py 2025-10-05 00:10:45.508409 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-05 00:10:45.544263 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00 2025-10-05 00:10:45.719365 | controller | Collecting pytest>=3.10 2025-10-05 00:10:45.731963 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-05 00:10:45.791113 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.5 MB/s eta 0:00:00 2025-10-05 00:10:45.845706 | controller | Collecting iniconfig>=1 2025-10-05 00:10:45.858265 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-05 00:10:45.925890 | controller | Collecting packaging>=20 2025-10-05 00:10:45.937757 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-05 00:10:45.948985 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.8 MB/s eta 0:00:00 2025-10-05 00:10:45.994270 | controller | Collecting pluggy<2,>=1.5 2025-10-05 00:10:46.005876 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-05 00:10:46.082227 | controller | Collecting pygments>=2.7.2 2025-10-05 00:10:46.094112 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-05 00:10:46.208432 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.9 MB/s eta 0:00:00 2025-10-05 00:10:46.286032 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-05 00:10:48.235564 | 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-05 00:10:48.251538 | controller | 2025-10-05 00:10:48.428516 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-05 00:10:48.428568 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-05 00:10:48.812450 | controller | ok: Runtime: 0:00:03.800290 2025-10-05 00:10:48.818923 | 2025-10-05 00:10:48.819027 | TASK [Update pip] 2025-10-05 00:10:50.120281 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-05 00:10:50.396899 | controller | Collecting pip 2025-10-05 00:10:50.487419 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-05 00:10:50.669345 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.0 MB/s eta 0:00:00 2025-10-05 00:10:50.836846 | controller | Installing collected packages: pip 2025-10-05 00:10:50.837270 | controller | Attempting uninstall: pip 2025-10-05 00:10:50.841876 | controller | Found existing installation: pip 22.2.2 2025-10-05 00:10:51.126081 | controller | Uninstalling pip-22.2.2: 2025-10-05 00:10:51.156049 | controller | Successfully uninstalled pip-22.2.2 2025-10-05 00:10:52.892929 | controller | Successfully installed pip-25.2 2025-10-05 00:10:53.459052 | controller | ok: Runtime: 0:00:03.726935 2025-10-05 00:10:53.472562 | 2025-10-05 00:10:53.472882 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-05 00:10:53.978862 | controller | changed 2025-10-05 00:10:53.985485 | 2025-10-05 00:10:53.985577 | TASK [Install ansible into virtualenv] 2025-10-05 00:10:55.011481 | controller | Processing ./src/github.com/ansible/ansible 2025-10-05 00:10:55.018154 | controller | Installing build dependencies: started 2025-10-05 00:10:56.890843 | controller | Installing build dependencies: finished with status 'done' 2025-10-05 00:10:58.407456 | controller | Getting requirements to build wheel: started 2025-10-05 00:10:58.407517 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-05 00:10:58.410826 | controller | Preparing metadata (pyproject.toml): started 2025-10-05 00:10:59.336824 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-05 00:10:59.341219 | 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-05 00:10:59.341269 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-05 00:10:59.645822 | controller | ERROR 2025-10-05 00:10:59.646093 | controller | { 2025-10-05 00:10:59.646154 | controller | "delta": "0:00:05.102973", 2025-10-05 00:10:59.646197 | controller | "end": "2025-10-05 00:10:59.494709", 2025-10-05 00:10:59.646236 | controller | "msg": "non-zero return code", 2025-10-05 00:10:59.646294 | controller | "rc": 1, 2025-10-05 00:10:59.646334 | controller | "start": "2025-10-05 00:10:54.391736" 2025-10-05 00:10:59.646369 | controller | } failure 2025-10-05 00:10:59.648776 | 2025-10-05 00:10:59.648881 | PLAY RECAP 2025-10-05 00:10:59.648968 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-05 00:10:59.649059 | 2025-10-05 00:10:59.794068 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-05 00:10:59.795065 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-05 00:11:00.372869 | 2025-10-05 00:11:00.373036 | PLAY [all] 2025-10-05 00:11:00.395482 | 2025-10-05 00:11:00.395630 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-05 00:11:01.187371 | controller | changed: non-zero return code 2025-10-05 00:11:01.194985 | 2025-10-05 00:11:01.195168 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-05 00:11:01.223231 | controller | skipping: Conditional result was False 2025-10-05 00:11:01.229806 | 2025-10-05 00:11:01.229894 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-05 00:11:01.261322 | 2025-10-05 00:11:01.261499 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-05 00:11:01.292925 | 2025-10-05 00:11:01.293110 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-05 00:11:01.307908 | controller | skipping: Conditional result was False 2025-10-05 00:11:01.315270 | 2025-10-05 00:11:01.315380 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-05 00:11:01.347198 | 2025-10-05 00:11:01.347375 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-05 00:11:01.371339 | controller | skipping: Conditional result was False 2025-10-05 00:11:01.377990 | 2025-10-05 00:11:01.378086 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-05 00:11:01.402049 | controller | skipping: Conditional result was False 2025-10-05 00:11:01.408653 | 2025-10-05 00:11:01.408774 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-05 00:11:01.423713 | controller | skipping: Conditional result was False 2025-10-05 00:11:01.450942 | 2025-10-05 00:11:01.451093 | PLAY RECAP 2025-10-05 00:11:01.451141 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-05 00:11:01.451161 | 2025-10-05 00:11:01.556963 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-05 00:11:01.557781 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-05 00:11:02.245666 | 2025-10-05 00:11:02.245804 | PLAY [all:!appliance*] 2025-10-05 00:11:02.270986 | 2025-10-05 00:11:02.271100 | TASK [unregister the node] 2025-10-05 00:11:02.401985 | controller | skipping: Conditional result was False 2025-10-05 00:11:02.407806 | 2025-10-05 00:11:02.407881 | TASK [include_role : fetch-output] 2025-10-05 00:11:02.470327 | controller | ok 2025-10-05 00:11:02.489828 | 2025-10-05 00:11:02.489944 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-05 00:11:02.545573 | controller | skipping: Conditional result was False 2025-10-05 00:11:02.551430 | 2025-10-05 00:11:02.551504 | TASK [fetch-output : Set log path for single node] 2025-10-05 00:11:02.594133 | controller | ok 2025-10-05 00:11:02.602374 | 2025-10-05 00:11:02.602492 | LOOP [fetch-output : Ensure local output dirs] 2025-10-05 00:11:03.037412 | controller -> localhost | ok: "/var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/work/logs" 2025-10-05 00:11:03.285200 | controller -> localhost | changed: "/var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/work/artifacts" 2025-10-05 00:11:03.510560 | controller -> localhost | changed: "/var/lib/zuul/builds/f2c2aedfe9ba4088b3f0b51dd8ea0ca6/work/docs" 2025-10-05 00:11:03.526833 | 2025-10-05 00:11:03.526976 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-05 00:11:04.816092 | controller | changed: 2025-10-05 00:11:04.816297 | controller | .d..t...... ./ 2025-10-05 00:11:04.816327 | controller | cd+++++++++ controller/ 2025-10-05 00:11:04.816359 | controller | changed: All items complete 2025-10-05 00:11:04.816381 | 2025-10-05 00:11:05.890252 | controller | changed: .d..t...... ./ 2025-10-05 00:11:06.940864 | controller | changed: .d..t...... ./ 2025-10-05 00:11:06.960307 | 2025-10-05 00:11:06.960462 | TASK [include_role : fetch-output-openshift] 2025-10-05 00:11:06.975427 | controller | skipping: Conditional result was False 2025-10-05 00:11:06.984380 | 2025-10-05 00:11:06.984493 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-05 00:11:07.008996 | controller | skipping: Conditional result was False 2025-10-05 00:11:07.017338 | controller | skipping: Conditional result was False 2025-10-05 00:11:07.064365 | 2025-10-05 00:11:07.064489 | PLAY [localhost] 2025-10-05 00:11:07.078333 | 2025-10-05 00:11:07.078461 | TASK [Run Zuul manifest role] 2025-10-05 00:11:07.097788 | localhost | ok 2025-10-05 00:11:07.111777 | 2025-10-05 00:11:07.111908 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-05 00:11:07.512901 | localhost | changed 2025-10-05 00:11:07.523348 | 2025-10-05 00:11:07.523567 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-05 00:11:07.554222 | localhost | ok 2025-10-05 00:11:07.564487 | 2025-10-05 00:11:07.564582 | TASK [Set zuul-log-path fact] 2025-10-05 00:11:07.585017 | localhost | ok 2025-10-05 00:11:07.604311 | 2025-10-05 00:11:07.604436 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-05 00:11:07.635946 | localhost | ok 2025-10-05 00:11:07.648824 | 2025-10-05 00:11:07.648971 | LOOP [Run upload-logs-swift role] 2025-10-05 00:11:07.675086 | localhost | Output suppressed because no_log was given 2025-10-05 00:11:07.704019 | 2025-10-05 00:11:07.704163 | TASK [Set zuul-log-path fact] 2025-10-05 00:11:07.730199 | localhost | skipping: Conditional result was False 2025-10-05 00:11:07.736555 | 2025-10-05 00:11:07.736663 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-05 00:11:08.139512 | localhost -> localhost | ok: Runtime: 0:00:00.005965 2025-10-05 00:11:08.144869 | 2025-10-05 00:11:08.144977 | TASK [upload-logs-swift : Upload logs to swift]