2025-11-05 00:12:07.569221 | Job console starting... 2025-11-05 00:12:07.577927 | Updating repositories 2025-11-05 00:12:07.697438 | Preparing job workspace 2025-11-05 00:12:11.410613 | Running Ansible setup... 2025-11-05 00:12:19.290606 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-05 00:12:19.925958 | 2025-11-05 00:12:19.926093 | PLAY [localhost] 2025-11-05 00:12:19.935052 | 2025-11-05 00:12:19.935151 | TASK [Gathering Facts] 2025-11-05 00:12:20.974186 | localhost | ok 2025-11-05 00:12:21.004503 | 2025-11-05 00:12:21.004707 | TASK [Setup log path fact] 2025-11-05 00:12:21.027985 | localhost | ok 2025-11-05 00:12:21.045616 | 2025-11-05 00:12:21.045739 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-05 00:12:21.087414 | localhost | ok 2025-11-05 00:12:21.098717 | 2025-11-05 00:12:21.098810 | TASK [emit-job-header : Print job information] 2025-11-05 00:12:21.154025 | # Job Information 2025-11-05 00:12:21.154342 | Ansible Version: 2.15.12 2025-11-05 00:12:21.154437 | Job: ansible-test-sanity-docker-milestone 2025-11-05 00:12:21.154502 | Pipeline: periodic 2025-11-05 00:12:21.154560 | Executor: ze02.softwarefactory-project.io 2025-11-05 00:12:21.154616 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-05 00:12:21.154754 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/57e/ansible/57ef3b1fcd5248f59a36ed8786a479b8/ 2025-11-05 00:12:21.154809 | Event ID: f882144cc95d49c4bd339e6865f42051 2025-11-05 00:12:21.164654 | 2025-11-05 00:12:21.164905 | LOOP [emit-job-header : Print node information] 2025-11-05 00:12:21.278788 | localhost | ok: 2025-11-05 00:12:21.279078 | localhost | # Node Information 2025-11-05 00:12:21.279139 | localhost | Inventory Hostname: controller 2025-11-05 00:12:21.279183 | localhost | Hostname: np0005512075 2025-11-05 00:12:21.279224 | localhost | Username: zuul 2025-11-05 00:12:21.279268 | localhost | Distro: Fedora 37 2025-11-05 00:12:21.279307 | localhost | Provider: ansible-vexxhost-ams1 2025-11-05 00:12:21.279344 | localhost | Region: ams1 2025-11-05 00:12:21.279382 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-05 00:12:21.279419 | localhost | Product Name: OpenStack Nova 2025-11-05 00:12:21.279455 | localhost | Interface IP: 38.129.16.180 2025-11-05 00:12:21.303157 | 2025-11-05 00:12:21.303397 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-05 00:12:21.739358 | localhost -> localhost | changed 2025-11-05 00:12:21.747961 | 2025-11-05 00:12:21.748044 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-05 00:12:22.732344 | localhost -> localhost | changed 2025-11-05 00:12:22.768369 | 2025-11-05 00:12:22.768497 | PLAY [all:!appliance*] 2025-11-05 00:12:22.797437 | 2025-11-05 00:12:22.797620 | TASK [include_role : start-zuul-console] 2025-11-05 00:12:22.820154 | controller | ok 2025-11-05 00:12:22.839957 | 2025-11-05 00:12:22.840061 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-05 00:12:23.794008 | controller | ok 2025-11-05 00:12:23.813483 | 2025-11-05 00:12:23.813604 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-05 00:12:26.277659 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-05 00:12:26.294577 | 2025-11-05 00:12:26.294791 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-05 00:12:26.666590 | controller | skipping: Conditional result was False 2025-11-05 00:12:26.682202 | 2025-11-05 00:12:26.682350 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-05 00:12:26.711004 | controller | skipping: Conditional result was False 2025-11-05 00:12:26.729249 | 2025-11-05 00:12:26.729411 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-05 00:12:26.758178 | controller | skipping: Conditional result was False 2025-11-05 00:12:26.779260 | 2025-11-05 00:12:26.779439 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-05 00:12:26.819455 | controller | skipping: Conditional result was False 2025-11-05 00:12:26.829372 | 2025-11-05 00:12:26.829471 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-05 00:12:26.855442 | controller | skipping: Conditional result was False 2025-11-05 00:12:26.866642 | 2025-11-05 00:12:26.866893 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-05 00:12:26.893084 | controller | skipping: Conditional result was False 2025-11-05 00:12:26.910397 | 2025-11-05 00:12:26.910527 | TASK [Disable Fedora Modular] 2025-11-05 00:12:27.886405 | controller | changed 2025-11-05 00:12:27.895541 | 2025-11-05 00:12:27.895787 | TASK [Enable EPEL] 2025-11-05 00:12:27.922086 | controller | skipping: Conditional result was False 2025-11-05 00:12:27.931911 | 2025-11-05 00:12:27.932108 | TASK [Register the RHEL node] 2025-11-05 00:12:28.343253 | 2025-11-05 00:12:28.343710 | TASK [Show the subscription-manager status] 2025-11-05 00:12:28.729985 | controller | skipping: Conditional result was False 2025-11-05 00:12:28.745913 | 2025-11-05 00:12:28.746134 | TASK [Enable EPEL on RHEL] 2025-11-05 00:12:29.130490 | controller | skipping: Conditional result was False 2025-11-05 00:12:29.141975 | 2025-11-05 00:12:29.142126 | TASK [Install git and tox] 2025-11-05 00:14:24.104897 | controller | changed 2025-11-05 00:14:24.121768 | 2025-11-05 00:14:24.121917 | TASK [include_role : prepare-workspace] 2025-11-05 00:14:24.157173 | controller | ok 2025-11-05 00:14:24.198939 | 2025-11-05 00:14:24.199064 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-05 00:14:25.015837 | controller | ok 2025-11-05 00:14:25.038386 | 2025-11-05 00:14:25.038618 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-05 00:14:40.376501 | controller | Output suppressed because no_log was given 2025-11-05 00:14:40.434292 | 2025-11-05 00:14:40.434421 | TASK [include_role : prepare-workspace-openshift] 2025-11-05 00:14:40.459446 | controller | skipping: Conditional result was False 2025-11-05 00:14:40.481585 | 2025-11-05 00:14:40.481661 | PLAY [all:!appliance] 2025-11-05 00:14:40.497922 | 2025-11-05 00:14:40.498050 | TASK [Run add-build-sshkey role (RSA)] 2025-11-05 00:14:40.539087 | controller | ok 2025-11-05 00:14:40.554061 | 2025-11-05 00:14:40.554160 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-05 00:14:40.834440 | controller -> localhost | ok 2025-11-05 00:14:40.846607 | 2025-11-05 00:14:40.846806 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-05 00:14:40.873802 | controller | ok 2025-11-05 00:14:40.895034 | controller | included: /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-05 00:14:40.903335 | 2025-11-05 00:14:40.903416 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-05 00:14:41.499323 | controller -> localhost | Generating public/private rsa key pair. 2025-11-05 00:14:41.499842 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/work/57ef3b1fcd5248f59a36ed8786a479b8_id_rsa. 2025-11-05 00:14:41.499929 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/work/57ef3b1fcd5248f59a36ed8786a479b8_id_rsa.pub. 2025-11-05 00:14:41.499988 | controller -> localhost | The key fingerprint is: 2025-11-05 00:14:41.500043 | controller -> localhost | SHA256:b9LPCUr2G1Rnw0dMNdw8vQBy0yvPrVo5vMwAPp9jM5U zuul-build-sshkey 2025-11-05 00:14:41.500097 | controller -> localhost | The key's randomart image is: 2025-11-05 00:14:41.500148 | controller -> localhost | +---[RSA 2048]----+ 2025-11-05 00:14:41.500198 | controller -> localhost | | . +o .=B| 2025-11-05 00:14:41.500287 | controller -> localhost | | o .+ +*| 2025-11-05 00:14:41.500340 | controller -> localhost | | . B +| 2025-11-05 00:14:41.500392 | controller -> localhost | | o + + | 2025-11-05 00:14:41.500442 | controller -> localhost | | S.. + o | 2025-11-05 00:14:41.500514 | controller -> localhost | | .+. .E.. | 2025-11-05 00:14:41.500586 | controller -> localhost | | +o*..=. | 2025-11-05 00:14:41.500646 | controller -> localhost | | o =oX*oo | 2025-11-05 00:14:41.500750 | controller -> localhost | | . +=O+ | 2025-11-05 00:14:41.500813 | controller -> localhost | +----[SHA256]-----+ 2025-11-05 00:14:41.500934 | controller -> localhost | ok: Runtime: 0:00:00.145746 2025-11-05 00:14:41.517287 | 2025-11-05 00:14:41.517434 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-05 00:14:41.555929 | controller | ok 2025-11-05 00:14:41.569498 | controller | included: /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-05 00:14:41.582034 | 2025-11-05 00:14:41.582153 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-05 00:14:41.609624 | controller | skipping: Conditional result was False 2025-11-05 00:14:41.619337 | 2025-11-05 00:14:41.619450 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-05 00:14:42.649126 | controller | changed 2025-11-05 00:14:42.660879 | 2025-11-05 00:14:42.661109 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-05 00:14:43.294531 | controller | ok 2025-11-05 00:14:43.308948 | 2025-11-05 00:14:43.309131 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-05 00:14:46.274222 | controller | changed 2025-11-05 00:14:46.286855 | 2025-11-05 00:14:46.287000 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-05 00:14:49.243244 | controller | changed 2025-11-05 00:14:49.254089 | 2025-11-05 00:14:49.254206 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-05 00:14:49.292268 | controller | skipping: Conditional result was False 2025-11-05 00:14:49.305037 | 2025-11-05 00:14:49.305167 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-05 00:14:49.763083 | controller -> localhost | changed 2025-11-05 00:14:49.780562 | 2025-11-05 00:14:49.780707 | TASK [add-build-sshkey : Add back temp key] 2025-11-05 00:14:50.051413 | controller -> localhost | Identity added: /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/work/57ef3b1fcd5248f59a36ed8786a479b8_id_rsa (zuul-build-sshkey) 2025-11-05 00:14:50.051756 | controller -> localhost | ok: Runtime: 0:00:00.008862 2025-11-05 00:14:50.061514 | 2025-11-05 00:14:50.061613 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-05 00:14:51.023062 | controller | ok 2025-11-05 00:14:51.038778 | 2025-11-05 00:14:51.038934 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-05 00:14:51.078899 | controller | skipping: Conditional result was False 2025-11-05 00:14:51.110257 | 2025-11-05 00:14:51.110441 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-05 00:14:51.149883 | controller | ok 2025-11-05 00:14:51.179689 | 2025-11-05 00:14:51.179832 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-05 00:14:51.443318 | controller -> localhost | ok 2025-11-05 00:14:51.451830 | 2025-11-05 00:14:51.451908 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-05 00:14:51.485406 | controller | ok 2025-11-05 00:14:51.498005 | controller | included: /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-05 00:14:51.504824 | 2025-11-05 00:14:51.504903 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-05 00:14:51.768729 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-05 00:14:51.769056 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/work/57ef3b1fcd5248f59a36ed8786a479b8_id_ecdsa. 2025-11-05 00:14:51.769115 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/work/57ef3b1fcd5248f59a36ed8786a479b8_id_ecdsa.pub. 2025-11-05 00:14:51.769174 | controller -> localhost | The key fingerprint is: 2025-11-05 00:14:51.769217 | controller -> localhost | SHA256:LqIQZP0gWyXpMoH0f2d+dmXvvlldMm9varnj1Rz9BXs zuul-build-sshkey 2025-11-05 00:14:51.769257 | controller -> localhost | The key's randomart image is: 2025-11-05 00:14:51.769297 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-05 00:14:51.769335 | controller -> localhost | |o. ... | 2025-11-05 00:14:51.769373 | controller -> localhost | |..o.o | 2025-11-05 00:14:51.769410 | controller -> localhost | | +o= . | 2025-11-05 00:14:51.769447 | controller -> localhost | |oo+.+ o.| 2025-11-05 00:14:51.769484 | controller -> localhost | |..o o .So ++E| 2025-11-05 00:14:51.769548 | controller -> localhost | | . ..+ o*O| 2025-11-05 00:14:51.769589 | controller -> localhost | |. . . .. o . .@| 2025-11-05 00:14:51.769626 | controller -> localhost | | . . . . o . ++=| 2025-11-05 00:14:51.769700 | controller -> localhost | | . o+O=| 2025-11-05 00:14:51.769749 | controller -> localhost | +----[SHA256]-----+ 2025-11-05 00:14:51.769844 | controller -> localhost | ok: Runtime: 0:00:00.012205 2025-11-05 00:14:51.786910 | 2025-11-05 00:14:51.787082 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-05 00:14:51.831754 | controller | ok 2025-11-05 00:14:51.849394 | controller | included: /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-05 00:14:51.865106 | 2025-11-05 00:14:51.865254 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-05 00:14:51.893234 | controller | skipping: Conditional result was False 2025-11-05 00:14:51.902084 | 2025-11-05 00:14:51.902176 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-05 00:14:52.783599 | controller | changed 2025-11-05 00:14:52.848227 | 2025-11-05 00:14:52.848366 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-05 00:14:53.472315 | controller | ok 2025-11-05 00:14:53.486234 | 2025-11-05 00:14:53.486408 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-05 00:14:56.332746 | controller | changed 2025-11-05 00:14:56.347548 | 2025-11-05 00:14:56.348076 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-05 00:14:59.233822 | controller | changed 2025-11-05 00:14:59.249727 | 2025-11-05 00:14:59.249999 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-05 00:14:59.279162 | controller | skipping: Conditional result was False 2025-11-05 00:14:59.291200 | 2025-11-05 00:14:59.291390 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-05 00:14:59.544423 | controller -> localhost | changed 2025-11-05 00:14:59.573074 | 2025-11-05 00:14:59.573310 | TASK [add-build-sshkey : Add back temp key] 2025-11-05 00:15:00.035277 | controller -> localhost | Identity added: /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/work/57ef3b1fcd5248f59a36ed8786a479b8_id_ecdsa (zuul-build-sshkey) 2025-11-05 00:15:00.035517 | controller -> localhost | ok: Runtime: 0:00:00.016466 2025-11-05 00:15:00.044595 | 2025-11-05 00:15:00.044732 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-05 00:15:00.703949 | controller | ok 2025-11-05 00:15:00.712388 | 2025-11-05 00:15:00.712459 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-05 00:15:00.752207 | controller | skipping: Conditional result was False 2025-11-05 00:15:00.766254 | 2025-11-05 00:15:00.766338 | TASK [include_role : remove-zuul-sshkey] 2025-11-05 00:15:00.805870 | controller | skipping: Conditional result was False 2025-11-05 00:15:00.816558 | 2025-11-05 00:15:00.816652 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-05 00:15:01.429135 | controller | ok: "logs" 2025-11-05 00:15:01.429454 | controller | ok: All items complete 2025-11-05 00:15:01.429494 | 2025-11-05 00:15:02.017149 | controller | ok: "artifacts" 2025-11-05 00:15:02.597527 | controller | ok: "docs" 2025-11-05 00:15:02.624536 | 2025-11-05 00:15:02.624800 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-05 00:15:03.254579 | controller | changed: "logs" 2025-11-05 00:15:03.827356 | controller | changed: "artifacts" 2025-11-05 00:15:04.341387 | controller | changed: "docs" 2025-11-05 00:15:04.379181 | 2025-11-05 00:15:04.379337 | PLAY RECAP 2025-11-05 00:15:04.379389 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-05 00:15:04.379415 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-05 00:15:04.379433 | 2025-11-05 00:15:04.519861 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-05 00:15:04.521824 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-05 00:15:05.090935 | 2025-11-05 00:15:05.091048 | PLAY [all] 2025-11-05 00:15:05.112601 | 2025-11-05 00:15:05.112704 | TASK [Install binary dependencies] 2025-11-05 00:15:05.153336 | controller | ok 2025-11-05 00:15:05.173126 | 2025-11-05 00:15:05.173208 | TASK [bindep : Include find tasks] 2025-11-05 00:15:05.213503 | controller | ok 2025-11-05 00:15:05.221405 | controller | included: /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-05 00:15:05.227693 | 2025-11-05 00:15:05.227757 | TASK [bindep : Look for bindep.txt] 2025-11-05 00:15:06.118432 | controller | ok 2025-11-05 00:15:06.134611 | 2025-11-05 00:15:06.134877 | TASK [bindep : Define bindep_file fact] 2025-11-05 00:15:06.162693 | controller | skipping: Conditional result was False 2025-11-05 00:15:06.173969 | 2025-11-05 00:15:06.174186 | TASK [bindep : Look for other-requirements.txt] 2025-11-05 00:15:06.795423 | controller | ok 2025-11-05 00:15:06.807622 | 2025-11-05 00:15:06.807795 | TASK [bindep : Define bindep_file fact] 2025-11-05 00:15:06.832046 | controller | skipping: Conditional result was False 2025-11-05 00:15:06.839181 | 2025-11-05 00:15:06.839281 | TASK [bindep : Look for bindep fallback file] 2025-11-05 00:15:06.863493 | controller | skipping: Conditional result was False 2025-11-05 00:15:06.870402 | 2025-11-05 00:15:06.870513 | TASK [bindep : Define bindep_file fact] 2025-11-05 00:15:06.894514 | controller | skipping: Conditional result was False 2025-11-05 00:15:06.901425 | 2025-11-05 00:15:06.901503 | TASK [bindep : Include bindep tasks] 2025-11-05 00:15:06.925456 | controller | skipping: Conditional result was False 2025-11-05 00:15:06.932486 | 2025-11-05 00:15:06.932595 | TASK [bindep : Include install tasks] 2025-11-05 00:15:06.966862 | controller | skipping: Conditional result was False 2025-11-05 00:15:06.973790 | 2025-11-05 00:15:06.973880 | LOOP [bindep : Include package tasks] 2025-11-05 00:15:07.032288 | 2025-11-05 00:15:07.032594 | TASK [Run test-setup role] 2025-11-05 00:15:07.053367 | controller | ok 2025-11-05 00:15:07.073740 | 2025-11-05 00:15:07.073882 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-05 00:15:07.744755 | controller | ok 2025-11-05 00:15:07.754784 | 2025-11-05 00:15:07.754903 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-05 00:15:08.148815 | controller | skipping: Conditional result was False 2025-11-05 00:15:08.186358 | 2025-11-05 00:15:08.186491 | PLAY RECAP 2025-11-05 00:15:08.186535 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-05 00:15:08.186569 | 2025-11-05 00:15:08.323721 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-05 00:15:08.324951 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-05 00:15:08.938878 | 2025-11-05 00:15:08.939050 | PLAY [controller] 2025-11-05 00:15:08.960459 | 2025-11-05 00:15:08.960549 | TASK [Create the /root directory] 2025-11-05 00:15:09.975798 | controller | ok 2025-11-05 00:15:09.982019 | 2025-11-05 00:15:09.982094 | TASK [Install glibc-langpack-en] 2025-11-05 00:15:16.957241 | controller | ok: Nothing to do 2025-11-05 00:15:16.971988 | 2025-11-05 00:15:16.972143 | TASK [Ensure controller directory exists] 2025-11-05 00:15:17.752629 | controller | changed 2025-11-05 00:15:17.767240 | 2025-11-05 00:15:17.767391 | TASK [Install container runtime] 2025-11-05 00:15:17.852161 | controller | ok 2025-11-05 00:15:17.913948 | 2025-11-05 00:15:17.914134 | LOOP [ensure-podman : Find distribution installation] 2025-11-05 00:15:17.966745 | controller | ok: "/var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-05 00:15:17.980126 | controller | included: /var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-05 00:15:17.986781 | 2025-11-05 00:15:17.986849 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-05 00:17:10.933210 | controller | changed 2025-11-05 00:17:10.950011 | 2025-11-05 00:17:10.950187 | TASK [ensure-podman : Fetch podman version] 2025-11-05 00:17:12.061511 | controller | Client: Podman Engine 2025-11-05 00:17:12.061628 | controller | Version: 4.6.2 2025-11-05 00:17:12.061675 | controller | API Version: 4.6.2 2025-11-05 00:17:12.061716 | controller | Go Version: go1.19.12 2025-11-05 00:17:12.061785 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-05 00:17:12.061828 | controller | OS/Arch: linux/amd64 2025-11-05 00:17:12.320212 | controller | ok: Runtime: 0:00:00.236428 2025-11-05 00:17:12.336616 | 2025-11-05 00:17:12.336916 | TASK [ensure-podman : Print podman version installed] 2025-11-05 00:17:12.392034 | Podman version: Client: Podman Engine 2025-11-05 00:17:12.392397 | Version: 4.6.2 2025-11-05 00:17:12.392467 | API Version: 4.6.2 2025-11-05 00:17:12.392515 | Go Version: go1.19.12 2025-11-05 00:17:12.392558 | Built: Mon Aug 28 19:38:31 2023 2025-11-05 00:17:12.392603 | OS/Arch: linux/amd64 2025-11-05 00:17:12.420937 | 2025-11-05 00:17:12.421151 | TASK [ensure-podman : Validate podman engine] 2025-11-05 00:17:12.799650 | controller | skipping: Conditional result was False 2025-11-05 00:17:12.807159 | 2025-11-05 00:17:12.807247 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-05 00:17:12.833752 | controller | skipping: Conditional result was False 2025-11-05 00:17:12.851038 | 2025-11-05 00:17:12.851833 | TASK [Ensure python3.8 is present] 2025-11-05 00:17:12.889231 | controller | skipping: Conditional result was False 2025-11-05 00:17:12.901116 | 2025-11-05 00:17:12.901244 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-05 00:17:12.929182 | controller | ok 2025-11-05 00:17:12.962545 | 2025-11-05 00:17:12.962712 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-05 00:17:15.976761 | controller | ok: Nothing to do 2025-11-05 00:17:15.983938 | 2025-11-05 00:17:15.984053 | TASK [our-ensure-python : Also install python3-devel] 2025-11-05 00:17:33.219532 | controller | changed 2025-11-05 00:17:33.246959 | 2025-11-05 00:17:33.247166 | TASK [Run ensure-virtualenv role] 2025-11-05 00:17:33.279956 | controller | ok 2025-11-05 00:17:33.311277 | 2025-11-05 00:17:33.311470 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-05 00:17:34.104280 | controller | /usr/bin/virtualenv 2025-11-05 00:17:34.722308 | controller | ok: Runtime: 0:00:00.006181 2025-11-05 00:17:34.731547 | 2025-11-05 00:17:34.731749 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-05 00:17:34.774589 | controller | skipping: Conditional result was False 2025-11-05 00:17:34.775179 | controller | ok: All items complete 2025-11-05 00:17:34.775252 | 2025-11-05 00:17:34.790790 | 2025-11-05 00:17:34.790942 | TASK [Find the full path of the Python interpreter] 2025-11-05 00:17:35.521324 | controller | /usr/bin/python3 2025-11-05 00:17:35.646106 | controller | ok 2025-11-05 00:17:35.658848 | 2025-11-05 00:17:35.659020 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-05 00:17:37.274243 | controller | created virtual environment CPython3.11.0.final.0-64 in 825ms 2025-11-05 00:17:37.335214 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-05 00:17:37.336093 | 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-11-05 00:17:37.336304 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-05 00:17:37.336639 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-05 00:17:37.536650 | controller | changed 2025-11-05 00:17:37.551797 | 2025-11-05 00:17:37.551944 | TASK [Set selinux package] 2025-11-05 00:17:37.599696 | controller | ok 2025-11-05 00:17:37.607191 | 2025-11-05 00:17:37.607278 | TASK [Set selinux package (Fedora)] 2025-11-05 00:17:37.664875 | controller | ok 2025-11-05 00:17:37.672001 | 2025-11-05 00:17:37.672077 | TASK [Install selinux into virtualenv] 2025-11-05 00:17:40.232670 | controller | Collecting selinux-please-lie-to-me 2025-11-05 00:17:40.287138 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-05 00:17:40.739304 | controller | Collecting setuptools<50.0.0 2025-11-05 00:17:40.744615 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-05 00:17:40.789902 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 19.7 MB/s eta 0:00:00 2025-11-05 00:17:40.901163 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-05 00:17:40.901512 | controller | Attempting uninstall: setuptools 2025-11-05 00:17:40.905039 | controller | Found existing installation: setuptools 62.6.0 2025-11-05 00:17:40.991634 | controller | Uninstalling setuptools-62.6.0: 2025-11-05 00:17:41.003621 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-05 00:17:41.598878 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-05 00:17:41.760887 | controller | 2025-11-05 00:17:41.988283 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-05 00:17:41.988340 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-05 00:17:42.536431 | controller | ok: Runtime: 0:00:03.498097 2025-11-05 00:17:42.549621 | 2025-11-05 00:17:42.549891 | TASK [Install pytest-forked into virtualenv] 2025-11-05 00:17:44.048145 | controller | Collecting pytest-forked 2025-11-05 00:17:44.106319 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-05 00:17:44.154761 | controller | Collecting py 2025-11-05 00:17:44.161514 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-05 00:17:44.191681 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00 2025-11-05 00:17:44.338907 | controller | Collecting pytest>=3.10 2025-11-05 00:17:44.343346 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-11-05 00:17:44.362056 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 23.5 MB/s eta 0:00:00 2025-11-05 00:17:44.404375 | controller | Collecting iniconfig>=1 2025-11-05 00:17:44.408463 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-05 00:17:44.459565 | controller | Collecting packaging>=20 2025-11-05 00:17:44.463510 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-05 00:17:44.470875 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 12.9 MB/s eta 0:00:00 2025-11-05 00:17:44.507459 | controller | Collecting pluggy<2,>=1.5 2025-11-05 00:17:44.511430 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-05 00:17:44.571065 | controller | Collecting pygments>=2.7.2 2025-11-05 00:17:44.575567 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-05 00:17:44.615027 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 42.6 MB/s eta 0:00:00 2025-11-05 00:17:44.729269 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-05 00:17:46.663474 | 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-05 00:17:46.685896 | controller | 2025-11-05 00:17:46.894638 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-05 00:17:46.894696 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-05 00:17:47.454192 | controller | ok: Runtime: 0:00:03.587334 2025-11-05 00:17:47.470858 | 2025-11-05 00:17:47.471075 | TASK [Update pip] 2025-11-05 00:17:48.780661 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-05 00:17:48.986040 | controller | Collecting pip 2025-11-05 00:17:49.038618 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-05 00:17:49.098542 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 33.1 MB/s eta 0:00:00 2025-11-05 00:17:49.213902 | controller | Installing collected packages: pip 2025-11-05 00:17:49.214216 | controller | Attempting uninstall: pip 2025-11-05 00:17:49.217480 | controller | Found existing installation: pip 22.2.2 2025-11-05 00:17:49.432511 | controller | Uninstalling pip-22.2.2: 2025-11-05 00:17:49.455243 | controller | Successfully uninstalled pip-22.2.2 2025-11-05 00:17:51.057765 | controller | Successfully installed pip-25.3 2025-11-05 00:17:51.893012 | controller | ok: Runtime: 0:00:02.973778 2025-11-05 00:17:51.899331 | 2025-11-05 00:17:51.899399 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-05 00:17:52.747557 | controller | changed 2025-11-05 00:17:52.753256 | 2025-11-05 00:17:52.753329 | TASK [Install ansible into virtualenv] 2025-11-05 00:17:53.809535 | controller | Processing ./src/github.com/ansible/ansible 2025-11-05 00:17:53.814502 | controller | Installing build dependencies: started 2025-11-05 00:17:55.351346 | controller | Installing build dependencies: finished with status 'done' 2025-11-05 00:17:56.934885 | controller | Getting requirements to build wheel: started 2025-11-05 00:17:56.934984 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-05 00:17:56.940650 | controller | Preparing metadata (pyproject.toml): started 2025-11-05 00:17:57.677325 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-05 00:17:57.681024 | 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-05 00:17:57.684756 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-05 00:17:58.115786 | controller | ERROR 2025-11-05 00:17:58.116056 | controller | { 2025-11-05 00:17:58.116085 | controller | "delta": "0:00:04.475950", 2025-11-05 00:17:58.116106 | controller | "end": "2025-11-05 00:17:57.826683", 2025-11-05 00:17:58.116124 | controller | "msg": "non-zero return code", 2025-11-05 00:17:58.116153 | controller | "rc": 1, 2025-11-05 00:17:58.116171 | controller | "start": "2025-11-05 00:17:53.350733" 2025-11-05 00:17:58.116188 | controller | } failure 2025-11-05 00:17:58.117993 | 2025-11-05 00:17:58.118043 | PLAY RECAP 2025-11-05 00:17:58.118087 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-05 00:17:58.118108 | 2025-11-05 00:17:58.258710 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-05 00:17:58.259961 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-05 00:17:58.939430 | 2025-11-05 00:17:58.939650 | PLAY [all] 2025-11-05 00:17:58.969364 | 2025-11-05 00:17:58.969612 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-05 00:18:00.774323 | controller | changed: non-zero return code 2025-11-05 00:18:00.791081 | 2025-11-05 00:18:00.791368 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-05 00:18:00.821844 | controller | skipping: Conditional result was False 2025-11-05 00:18:00.832276 | 2025-11-05 00:18:00.832462 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-05 00:18:00.879607 | 2025-11-05 00:18:00.879902 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-05 00:18:00.915017 | 2025-11-05 00:18:00.915288 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-05 00:18:00.941316 | controller | skipping: Conditional result was False 2025-11-05 00:18:00.952065 | 2025-11-05 00:18:00.952441 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-05 00:18:00.988901 | 2025-11-05 00:18:00.989085 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-05 00:18:01.004018 | controller | skipping: Conditional result was False 2025-11-05 00:18:01.010505 | 2025-11-05 00:18:01.010571 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-05 00:18:01.034271 | controller | skipping: Conditional result was False 2025-11-05 00:18:01.040327 | 2025-11-05 00:18:01.040392 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-05 00:18:01.054553 | controller | skipping: Conditional result was False 2025-11-05 00:18:01.081637 | 2025-11-05 00:18:01.081719 | PLAY RECAP 2025-11-05 00:18:01.081761 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-05 00:18:01.081781 | 2025-11-05 00:18:01.192755 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-05 00:18:01.193710 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-05 00:18:01.889474 | 2025-11-05 00:18:01.889659 | PLAY [all:!appliance*] 2025-11-05 00:18:01.916341 | 2025-11-05 00:18:01.916485 | TASK [unregister the node] 2025-11-05 00:18:02.271462 | controller | skipping: Conditional result was False 2025-11-05 00:18:02.285475 | 2025-11-05 00:18:02.285693 | TASK [include_role : fetch-output] 2025-11-05 00:18:02.346444 | controller | ok 2025-11-05 00:18:02.391930 | 2025-11-05 00:18:02.392070 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-05 00:18:02.450044 | controller | skipping: Conditional result was False 2025-11-05 00:18:02.459581 | 2025-11-05 00:18:02.459760 | TASK [fetch-output : Set log path for single node] 2025-11-05 00:18:02.505133 | controller | ok 2025-11-05 00:18:02.513030 | 2025-11-05 00:18:02.513123 | LOOP [fetch-output : Ensure local output dirs] 2025-11-05 00:18:02.980488 | controller -> localhost | ok: "/var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/work/logs" 2025-11-05 00:18:03.214096 | controller -> localhost | changed: "/var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/work/artifacts" 2025-11-05 00:18:03.440507 | controller -> localhost | changed: "/var/lib/zuul/builds/57ef3b1fcd5248f59a36ed8786a479b8/work/docs" 2025-11-05 00:18:03.451489 | 2025-11-05 00:18:03.451612 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-05 00:18:05.692917 | controller | changed: 2025-11-05 00:18:05.693385 | controller | .d..t...... ./ 2025-11-05 00:18:05.693433 | controller | cd+++++++++ controller/ 2025-11-05 00:18:05.693483 | controller | changed: All items complete 2025-11-05 00:18:05.693512 | 2025-11-05 00:18:07.750825 | controller | changed: .d..t...... ./ 2025-11-05 00:18:09.812048 | controller | changed: .d..t...... ./ 2025-11-05 00:18:09.844535 | 2025-11-05 00:18:09.844957 | TASK [include_role : fetch-output-openshift] 2025-11-05 00:18:09.874497 | controller | skipping: Conditional result was False 2025-11-05 00:18:09.884242 | 2025-11-05 00:18:09.884387 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-05 00:18:09.935490 | controller | skipping: Conditional result was False 2025-11-05 00:18:09.949823 | controller | skipping: Conditional result was False 2025-11-05 00:18:09.991349 | 2025-11-05 00:18:09.991513 | PLAY [localhost] 2025-11-05 00:18:10.010104 | 2025-11-05 00:18:10.010253 | TASK [Run Zuul manifest role] 2025-11-05 00:18:10.035699 | localhost | ok 2025-11-05 00:18:10.054567 | 2025-11-05 00:18:10.054731 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-05 00:18:10.545701 | localhost | changed 2025-11-05 00:18:10.551116 | 2025-11-05 00:18:10.551245 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-05 00:18:10.601426 | localhost | ok 2025-11-05 00:18:10.609438 | 2025-11-05 00:18:10.609498 | TASK [Set zuul-log-path fact] 2025-11-05 00:18:10.630372 | localhost | ok 2025-11-05 00:18:10.678226 | 2025-11-05 00:18:10.678375 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-05 00:18:10.708731 | localhost | ok 2025-11-05 00:18:10.717529 | 2025-11-05 00:18:10.717597 | LOOP [Run upload-logs-swift role] 2025-11-05 00:18:10.753722 | localhost | Output suppressed because no_log was given 2025-11-05 00:18:10.797242 | 2025-11-05 00:18:10.797444 | TASK [Set zuul-log-path fact] 2025-11-05 00:18:10.844431 | localhost | skipping: Conditional result was False 2025-11-05 00:18:10.859833 | 2025-11-05 00:18:10.860085 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-05 00:18:11.253097 | localhost -> localhost | ok: Runtime: 0:00:00.005254 2025-11-05 00:18:11.258834 | 2025-11-05 00:18:11.258916 | TASK [upload-logs-swift : Upload logs to swift]