2026-01-24 00:15:27.240125 | Job console starting... 2026-01-24 00:15:27.251784 | Updating repositories 2026-01-24 00:15:27.399716 | Preparing job workspace 2026-01-24 00:15:31.137350 | Running Ansible setup... 2026-01-24 00:15:39.023878 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2026-01-24 00:15:39.655771 | 2026-01-24 00:15:39.655889 | PLAY [localhost] 2026-01-24 00:15:39.664272 | 2026-01-24 00:15:39.664359 | TASK [Gathering Facts] 2026-01-24 00:15:40.817498 | localhost | ok 2026-01-24 00:15:40.844820 | 2026-01-24 00:15:40.845004 | TASK [Setup log path fact] 2026-01-24 00:15:40.878142 | localhost | ok 2026-01-24 00:15:40.891512 | 2026-01-24 00:15:40.891585 | TASK [set-zuul-log-path-fact : Set log path for a build] 2026-01-24 00:15:40.931899 | localhost | ok 2026-01-24 00:15:40.940001 | 2026-01-24 00:15:40.940081 | TASK [emit-job-header : Print job information] 2026-01-24 00:15:40.988885 | # Job Information 2026-01-24 00:15:40.989075 | Ansible Version: 2.15.12 2026-01-24 00:15:40.989107 | Job: ansible-test-sanity-docker-devel 2026-01-24 00:15:40.989129 | Pipeline: periodic 2026-01-24 00:15:40.989148 | Executor: ze02.softwarefactory-project.io 2026-01-24 00:15:40.989166 | Triggered by: https://github.com/ansible-collections/ansible.network 2026-01-24 00:15:40.989188 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/3f4/ansible/3f48a7518deb487598bf25a2206d068c/ 2026-01-24 00:15:40.989208 | Event ID: 65eedbcb1f084ad8b98825c92073f9d7 2026-01-24 00:15:40.993445 | 2026-01-24 00:15:40.993509 | LOOP [emit-job-header : Print node information] 2026-01-24 00:15:41.098643 | localhost | ok: 2026-01-24 00:15:41.099797 | localhost | # Node Information 2026-01-24 00:15:41.099906 | localhost | Inventory Hostname: controller 2026-01-24 00:15:41.099962 | localhost | Hostname: np0005594204 2026-01-24 00:15:41.100010 | localhost | Username: zuul 2026-01-24 00:15:41.100090 | localhost | Distro: Fedora 37 2026-01-24 00:15:41.100141 | localhost | Provider: ansible-vexxhost-ams1 2026-01-24 00:15:41.100183 | localhost | Region: ams1 2026-01-24 00:15:41.100222 | localhost | Label: ansible-fedora-37-1vcpu 2026-01-24 00:15:41.100274 | localhost | Product Name: OpenStack Nova 2026-01-24 00:15:41.100335 | localhost | Interface IP: 38.129.16.109 2026-01-24 00:15:41.119950 | 2026-01-24 00:15:41.120156 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2026-01-24 00:15:41.547723 | localhost -> localhost | changed 2026-01-24 00:15:41.553713 | 2026-01-24 00:15:41.553792 | TASK [log-inventory : Copy ansible inventory to logs dir] 2026-01-24 00:15:42.457699 | localhost -> localhost | changed 2026-01-24 00:15:42.491551 | 2026-01-24 00:15:42.491768 | PLAY [all:!appliance*] 2026-01-24 00:15:42.517442 | 2026-01-24 00:15:42.517573 | TASK [include_role : start-zuul-console] 2026-01-24 00:15:42.538722 | controller | ok 2026-01-24 00:15:42.552906 | 2026-01-24 00:15:42.553029 | TASK [start-zuul-console : Start zuul_console daemon.] 2026-01-24 00:15:43.572303 | controller | ok 2026-01-24 00:15:43.621821 | 2026-01-24 00:15:43.622118 | TASK [use-our-mirror : Retrieve the IP address] 2026-01-24 00:15:46.235412 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2026-01-24 00:15:46.251782 | 2026-01-24 00:15:46.251950 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2026-01-24 00:15:46.611093 | controller | skipping: Conditional result was False 2026-01-24 00:15:46.627388 | 2026-01-24 00:15:46.627563 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2026-01-24 00:15:46.657108 | controller | skipping: Conditional result was False 2026-01-24 00:15:46.687950 | 2026-01-24 00:15:46.688134 | TASK [use-our-mirror : Create the podman configuration directory] 2026-01-24 00:15:46.723915 | controller | skipping: Conditional result was False 2026-01-24 00:15:46.730928 | 2026-01-24 00:15:46.731017 | TASK [use-our-mirror : Copy the podman configuration] 2026-01-24 00:15:46.755235 | controller | skipping: Conditional result was False 2026-01-24 00:15:46.764150 | 2026-01-24 00:15:46.764242 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2026-01-24 00:15:46.779782 | controller | skipping: Conditional result was False 2026-01-24 00:15:46.789488 | 2026-01-24 00:15:46.789591 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2026-01-24 00:15:46.803998 | controller | skipping: Conditional result was False 2026-01-24 00:15:46.821909 | 2026-01-24 00:15:46.822052 | TASK [Disable Fedora Modular] 2026-01-24 00:15:47.922114 | controller | changed 2026-01-24 00:15:47.949334 | 2026-01-24 00:15:47.949519 | TASK [Enable EPEL] 2026-01-24 00:15:47.999813 | controller | skipping: Conditional result was False 2026-01-24 00:15:48.010231 | 2026-01-24 00:15:48.010383 | TASK [Register the RHEL node] 2026-01-24 00:15:48.471971 | 2026-01-24 00:15:48.472273 | TASK [Show the subscription-manager status] 2026-01-24 00:15:48.865445 | controller | skipping: Conditional result was False 2026-01-24 00:15:48.877403 | 2026-01-24 00:15:48.877598 | TASK [Enable EPEL on RHEL] 2026-01-24 00:15:49.260894 | controller | skipping: Conditional result was False 2026-01-24 00:15:49.272404 | 2026-01-24 00:15:49.272580 | TASK [Install git and tox] 2026-01-24 00:17:50.823699 | controller | changed 2026-01-24 00:17:50.838428 | 2026-01-24 00:17:50.838566 | TASK [include_role : prepare-workspace] 2026-01-24 00:17:50.881076 | controller | ok 2026-01-24 00:17:50.924503 | 2026-01-24 00:17:50.924705 | TASK [prepare-workspace : Start zuul_console daemon.] 2026-01-24 00:17:51.779448 | controller | ok 2026-01-24 00:17:51.799004 | 2026-01-24 00:17:51.799267 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2026-01-24 00:18:09.963360 | controller | Output suppressed because no_log was given 2026-01-24 00:18:09.978235 | 2026-01-24 00:18:09.978400 | TASK [include_role : prepare-workspace-openshift] 2026-01-24 00:18:10.005161 | controller | skipping: Conditional result was False 2026-01-24 00:18:10.074767 | 2026-01-24 00:18:10.074859 | PLAY [all:!appliance] 2026-01-24 00:18:10.091240 | 2026-01-24 00:18:10.091304 | TASK [Run add-build-sshkey role (RSA)] 2026-01-24 00:18:10.115462 | controller | ok 2026-01-24 00:18:10.134551 | 2026-01-24 00:18:10.134654 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2026-01-24 00:18:10.404254 | controller -> localhost | ok 2026-01-24 00:18:10.411660 | 2026-01-24 00:18:10.411750 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2026-01-24 00:18:10.457166 | controller | ok 2026-01-24 00:18:10.479798 | controller | included: /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2026-01-24 00:18:10.487100 | 2026-01-24 00:18:10.487206 | TASK [add-build-sshkey : Create Temp SSH key] 2026-01-24 00:18:11.115222 | controller -> localhost | Generating public/private rsa key pair. 2026-01-24 00:18:11.115568 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/work/3f48a7518deb487598bf25a2206d068c_id_rsa. 2026-01-24 00:18:11.115634 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/work/3f48a7518deb487598bf25a2206d068c_id_rsa.pub. 2026-01-24 00:18:11.115731 | controller -> localhost | The key fingerprint is: 2026-01-24 00:18:11.115779 | controller -> localhost | SHA256:GWk/mbVMuQ8GC/FGqu0akdc1CP9dwvyHFTQy4kH1w2A zuul-build-sshkey 2026-01-24 00:18:11.115820 | controller -> localhost | The key's randomart image is: 2026-01-24 00:18:11.115861 | controller -> localhost | +---[RSA 2048]----+ 2026-01-24 00:18:11.115899 | controller -> localhost | | o o+.E.+ | 2026-01-24 00:18:11.115939 | controller -> localhost | | O..++* o| 2026-01-24 00:18:11.115977 | controller -> localhost | | * *.* ++o| 2026-01-24 00:18:11.116016 | controller -> localhost | | = B @ = *.| 2026-01-24 00:18:11.116053 | controller -> localhost | | + S B B o o| 2026-01-24 00:18:11.116110 | controller -> localhost | | + o o .| 2026-01-24 00:18:11.116159 | controller -> localhost | | . . . | 2026-01-24 00:18:11.116201 | controller -> localhost | | o | 2026-01-24 00:18:11.116241 | controller -> localhost | | . | 2026-01-24 00:18:11.116286 | controller -> localhost | +----[SHA256]-----+ 2026-01-24 00:18:11.116374 | controller -> localhost | ok: Runtime: 0:00:00.166000 2026-01-24 00:18:11.134258 | 2026-01-24 00:18:11.134470 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2026-01-24 00:18:11.172012 | controller | ok 2026-01-24 00:18:11.190405 | controller | included: /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2026-01-24 00:18:11.205649 | 2026-01-24 00:18:11.205820 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2026-01-24 00:18:11.232145 | controller | skipping: Conditional result was False 2026-01-24 00:18:11.245341 | 2026-01-24 00:18:11.245636 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2026-01-24 00:18:12.312776 | controller | changed 2026-01-24 00:18:12.318916 | 2026-01-24 00:18:12.318986 | TASK [add-build-sshkey : Make sure user has a .ssh] 2026-01-24 00:18:12.968111 | controller | ok 2026-01-24 00:18:12.987543 | 2026-01-24 00:18:12.987840 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2026-01-24 00:18:16.030756 | controller | changed 2026-01-24 00:18:16.047922 | 2026-01-24 00:18:16.048105 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2026-01-24 00:18:19.043914 | controller | changed 2026-01-24 00:18:19.059020 | 2026-01-24 00:18:19.059254 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2026-01-24 00:18:19.097946 | controller | skipping: Conditional result was False 2026-01-24 00:18:19.115600 | 2026-01-24 00:18:19.115855 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2026-01-24 00:18:19.585999 | controller -> localhost | changed 2026-01-24 00:18:19.619071 | 2026-01-24 00:18:19.619301 | TASK [add-build-sshkey : Add back temp key] 2026-01-24 00:18:19.932792 | controller -> localhost | Identity added: /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/work/3f48a7518deb487598bf25a2206d068c_id_rsa (zuul-build-sshkey) 2026-01-24 00:18:19.933012 | controller -> localhost | ok: Runtime: 0:00:00.008019 2026-01-24 00:18:19.939689 | 2026-01-24 00:18:19.939778 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2026-01-24 00:18:20.861323 | controller | ok 2026-01-24 00:18:20.869764 | 2026-01-24 00:18:20.869875 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2026-01-24 00:18:20.896190 | controller | skipping: Conditional result was False 2026-01-24 00:18:20.923686 | 2026-01-24 00:18:20.923897 | TASK [Run add-build-sshkey role (ECDSA)] 2026-01-24 00:18:20.948962 | controller | ok 2026-01-24 00:18:20.972002 | 2026-01-24 00:18:20.972248 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2026-01-24 00:18:21.276360 | controller -> localhost | ok 2026-01-24 00:18:21.283466 | 2026-01-24 00:18:21.283539 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2026-01-24 00:18:21.318014 | controller | ok 2026-01-24 00:18:21.331911 | controller | included: /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2026-01-24 00:18:21.340250 | 2026-01-24 00:18:21.340392 | TASK [add-build-sshkey : Create Temp SSH key] 2026-01-24 00:18:21.692921 | controller -> localhost | Generating public/private ecdsa key pair. 2026-01-24 00:18:21.693157 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/work/3f48a7518deb487598bf25a2206d068c_id_ecdsa. 2026-01-24 00:18:21.693187 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/work/3f48a7518deb487598bf25a2206d068c_id_ecdsa.pub. 2026-01-24 00:18:21.693226 | controller -> localhost | The key fingerprint is: 2026-01-24 00:18:21.693246 | controller -> localhost | SHA256:M+IwAulmpvFtELxlJ0x9U4nrIVEHySHegXcFikij2Ck zuul-build-sshkey 2026-01-24 00:18:21.693266 | controller -> localhost | The key's randomart image is: 2026-01-24 00:18:21.693286 | controller -> localhost | +---[ECDSA 521]---+ 2026-01-24 00:18:21.693305 | controller -> localhost | | +..+=*++. | 2026-01-24 00:18:21.693323 | controller -> localhost | | = * +++B+o | 2026-01-24 00:18:21.693341 | controller -> localhost | |E * * ++o+ | 2026-01-24 00:18:21.693359 | controller -> localhost | |.o = o. o | 2026-01-24 00:18:21.693376 | controller -> localhost | |.=+ o .oS. | 2026-01-24 00:18:21.693394 | controller -> localhost | |=o + + ..o | 2026-01-24 00:18:21.693412 | controller -> localhost | |. . o . | 2026-01-24 00:18:21.693429 | controller -> localhost | | . | 2026-01-24 00:18:21.693447 | controller -> localhost | | | 2026-01-24 00:18:21.693466 | controller -> localhost | +----[SHA256]-----+ 2026-01-24 00:18:21.693518 | controller -> localhost | ok: Runtime: 0:00:00.011528 2026-01-24 00:18:21.701191 | 2026-01-24 00:18:21.701278 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2026-01-24 00:18:21.736288 | controller | ok 2026-01-24 00:18:21.753380 | controller | included: /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2026-01-24 00:18:21.768460 | 2026-01-24 00:18:21.768705 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2026-01-24 00:18:21.787513 | controller | skipping: Conditional result was False 2026-01-24 00:18:21.798912 | 2026-01-24 00:18:21.799064 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2026-01-24 00:18:22.678274 | controller | changed 2026-01-24 00:18:22.692627 | 2026-01-24 00:18:22.692805 | TASK [add-build-sshkey : Make sure user has a .ssh] 2026-01-24 00:18:23.355642 | controller | ok 2026-01-24 00:18:23.370247 | 2026-01-24 00:18:23.370660 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2026-01-24 00:18:26.393194 | controller | changed 2026-01-24 00:18:26.407816 | 2026-01-24 00:18:26.408028 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2026-01-24 00:18:29.602492 | controller | changed 2026-01-24 00:18:29.611612 | 2026-01-24 00:18:29.611830 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2026-01-24 00:18:29.651134 | controller | skipping: Conditional result was False 2026-01-24 00:18:29.662455 | 2026-01-24 00:18:29.662834 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2026-01-24 00:18:29.946235 | controller -> localhost | changed 2026-01-24 00:18:29.960034 | 2026-01-24 00:18:29.960134 | TASK [add-build-sshkey : Add back temp key] 2026-01-24 00:18:30.305975 | controller -> localhost | Identity added: /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/work/3f48a7518deb487598bf25a2206d068c_id_ecdsa (zuul-build-sshkey) 2026-01-24 00:18:30.306226 | controller -> localhost | ok: Runtime: 0:00:00.014935 2026-01-24 00:18:30.313894 | 2026-01-24 00:18:30.313975 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2026-01-24 00:18:31.040739 | controller | ok 2026-01-24 00:18:31.052781 | 2026-01-24 00:18:31.052878 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2026-01-24 00:18:31.089808 | controller | skipping: Conditional result was False 2026-01-24 00:18:31.111552 | 2026-01-24 00:18:31.111766 | TASK [include_role : remove-zuul-sshkey] 2026-01-24 00:18:31.138200 | controller | skipping: Conditional result was False 2026-01-24 00:18:31.150468 | 2026-01-24 00:18:31.150613 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2026-01-24 00:18:31.811870 | controller | ok: "logs" 2026-01-24 00:18:31.812195 | controller | ok: All items complete 2026-01-24 00:18:31.812252 | 2026-01-24 00:18:32.414487 | controller | ok: "artifacts" 2026-01-24 00:18:33.031588 | controller | ok: "docs" 2026-01-24 00:18:33.045296 | 2026-01-24 00:18:33.045478 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2026-01-24 00:18:33.701734 | controller | changed: "logs" 2026-01-24 00:18:34.329094 | controller | changed: "artifacts" 2026-01-24 00:18:35.006395 | controller | changed: "docs" 2026-01-24 00:18:35.053656 | 2026-01-24 00:18:35.053845 | PLAY RECAP 2026-01-24 00:18:35.053928 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2026-01-24 00:18:35.053966 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2026-01-24 00:18:35.053991 | 2026-01-24 00:18:35.214291 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2026-01-24 00:18:35.215246 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2026-01-24 00:18:35.927592 | 2026-01-24 00:18:35.927754 | PLAY [all] 2026-01-24 00:18:35.952514 | 2026-01-24 00:18:35.952717 | TASK [Install binary dependencies] 2026-01-24 00:18:36.014881 | controller | ok 2026-01-24 00:18:36.036519 | 2026-01-24 00:18:36.036648 | TASK [bindep : Include find tasks] 2026-01-24 00:18:36.077652 | controller | ok 2026-01-24 00:18:36.086442 | controller | included: /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2026-01-24 00:18:36.092931 | 2026-01-24 00:18:36.092999 | TASK [bindep : Look for bindep.txt] 2026-01-24 00:18:37.035236 | controller | ok 2026-01-24 00:18:37.048535 | 2026-01-24 00:18:37.048774 | TASK [bindep : Define bindep_file fact] 2026-01-24 00:18:37.075186 | controller | skipping: Conditional result was False 2026-01-24 00:18:37.089318 | 2026-01-24 00:18:37.089475 | TASK [bindep : Look for other-requirements.txt] 2026-01-24 00:18:37.699628 | controller | ok 2026-01-24 00:18:37.715305 | 2026-01-24 00:18:37.715541 | TASK [bindep : Define bindep_file fact] 2026-01-24 00:18:37.753010 | controller | skipping: Conditional result was False 2026-01-24 00:18:37.762972 | 2026-01-24 00:18:37.763108 | TASK [bindep : Look for bindep fallback file] 2026-01-24 00:18:37.800779 | controller | skipping: Conditional result was False 2026-01-24 00:18:37.812406 | 2026-01-24 00:18:37.812593 | TASK [bindep : Define bindep_file fact] 2026-01-24 00:18:37.839460 | controller | skipping: Conditional result was False 2026-01-24 00:18:37.846333 | 2026-01-24 00:18:37.846439 | TASK [bindep : Include bindep tasks] 2026-01-24 00:18:37.871302 | controller | skipping: Conditional result was False 2026-01-24 00:18:37.878685 | 2026-01-24 00:18:37.878810 | TASK [bindep : Include install tasks] 2026-01-24 00:18:37.903124 | controller | skipping: Conditional result was False 2026-01-24 00:18:37.909872 | 2026-01-24 00:18:37.909966 | LOOP [bindep : Include package tasks] 2026-01-24 00:18:37.967538 | 2026-01-24 00:18:37.967751 | TASK [Run test-setup role] 2026-01-24 00:18:37.987831 | controller | ok 2026-01-24 00:18:38.016641 | 2026-01-24 00:18:38.016796 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2026-01-24 00:18:38.740125 | controller | ok 2026-01-24 00:18:38.753834 | 2026-01-24 00:18:38.753974 | TASK [test-setup : Run tools/test-setup.sh] 2026-01-24 00:18:39.125544 | controller | skipping: Conditional result was False 2026-01-24 00:18:39.179509 | 2026-01-24 00:18:39.179645 | PLAY RECAP 2026-01-24 00:18:39.179747 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2026-01-24 00:18:39.179851 | 2026-01-24 00:18:39.309548 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2026-01-24 00:18:39.311121 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2026-01-24 00:18:39.980161 | 2026-01-24 00:18:39.980328 | PLAY [controller] 2026-01-24 00:18:40.002507 | 2026-01-24 00:18:40.002722 | TASK [Create the /root directory] 2026-01-24 00:18:41.103138 | controller | ok 2026-01-24 00:18:41.117566 | 2026-01-24 00:18:41.117842 | TASK [Install glibc-langpack-en] 2026-01-24 00:18:48.743793 | controller | ok: Nothing to do 2026-01-24 00:18:48.749682 | 2026-01-24 00:18:48.749810 | TASK [Ensure controller directory exists] 2026-01-24 00:18:49.555868 | controller | changed 2026-01-24 00:18:49.570615 | 2026-01-24 00:18:49.570834 | TASK [Install container runtime] 2026-01-24 00:18:49.641191 | controller | ok 2026-01-24 00:18:49.686746 | 2026-01-24 00:18:49.686904 | LOOP [ensure-podman : Find distribution installation] 2026-01-24 00:18:49.731283 | controller | ok: "/var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2026-01-24 00:18:49.740633 | controller | included: /var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2026-01-24 00:18:49.747568 | 2026-01-24 00:18:49.747642 | TASK [ensure-podman : Install podman (RedHat)] 2026-01-24 00:20:45.112435 | controller | changed 2026-01-24 00:20:45.130778 | 2026-01-24 00:20:45.130990 | TASK [ensure-podman : Fetch podman version] 2026-01-24 00:20:46.276937 | controller | Client: Podman Engine 2026-01-24 00:20:46.313201 | controller | Version: 4.6.2 2026-01-24 00:20:46.313254 | controller | API Version: 4.6.2 2026-01-24 00:20:46.313262 | controller | Go Version: go1.19.12 2026-01-24 00:20:46.313279 | controller | Built: Mon Aug 28 19:38:31 2023 2026-01-24 00:20:46.313287 | controller | OS/Arch: linux/amd64 2026-01-24 00:20:46.502777 | controller | ok: Runtime: 0:00:00.266080 2026-01-24 00:20:46.518998 | 2026-01-24 00:20:46.519217 | TASK [ensure-podman : Print podman version installed] 2026-01-24 00:20:46.566890 | Podman version: Client: Podman Engine 2026-01-24 00:20:46.567123 | Version: 4.6.2 2026-01-24 00:20:46.567163 | API Version: 4.6.2 2026-01-24 00:20:46.567192 | Go Version: go1.19.12 2026-01-24 00:20:46.567218 | Built: Mon Aug 28 19:38:31 2023 2026-01-24 00:20:46.567332 | OS/Arch: linux/amd64 2026-01-24 00:20:46.586592 | 2026-01-24 00:20:46.586879 | TASK [ensure-podman : Validate podman engine] 2026-01-24 00:20:46.958714 | controller | skipping: Conditional result was False 2026-01-24 00:20:46.978513 | 2026-01-24 00:20:46.978822 | TASK [ensure-podman : Set up docker compatability socket] 2026-01-24 00:20:47.008586 | controller | skipping: Conditional result was False 2026-01-24 00:20:47.031228 | 2026-01-24 00:20:47.031430 | TASK [Ensure python3.8 is present] 2026-01-24 00:20:47.060944 | controller | skipping: Conditional result was False 2026-01-24 00:20:47.070079 | 2026-01-24 00:20:47.070246 | TASK [Run our-ensure-python role (Fedora only for now)] 2026-01-24 00:20:47.095806 | controller | ok 2026-01-24 00:20:47.120566 | 2026-01-24 00:20:47.120772 | TASK [our-ensure-python : Install the right Python version (rpm)] 2026-01-24 00:20:50.743644 | controller | ok: Nothing to do 2026-01-24 00:20:50.760996 | 2026-01-24 00:20:50.761158 | TASK [our-ensure-python : Also install python3-devel] 2026-01-24 00:21:05.173412 | controller | changed 2026-01-24 00:21:05.199852 | 2026-01-24 00:21:05.200105 | TASK [Run ensure-virtualenv role] 2026-01-24 00:21:05.233806 | controller | ok 2026-01-24 00:21:05.259218 | 2026-01-24 00:21:05.259456 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2026-01-24 00:21:06.062688 | controller | /usr/bin/virtualenv 2026-01-24 00:21:06.668336 | controller | ok: Runtime: 0:00:00.004694 2026-01-24 00:21:06.684436 | 2026-01-24 00:21:06.684743 | LOOP [ensure-virtualenv : Install virtualenv package] 2026-01-24 00:21:06.729853 | controller | skipping: Conditional result was False 2026-01-24 00:21:06.730334 | controller | ok: All items complete 2026-01-24 00:21:06.730396 | 2026-01-24 00:21:06.761446 | 2026-01-24 00:21:06.761713 | TASK [Find the full path of the Python interpreter] 2026-01-24 00:21:07.520057 | controller | /usr/bin/python3 2026-01-24 00:21:08.135336 | controller | ok 2026-01-24 00:21:08.152535 | 2026-01-24 00:21:08.152754 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2026-01-24 00:21:09.985809 | controller | created virtual environment CPython3.11.0.final.0-64 in 839ms 2026-01-24 00:21:10.055357 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2026-01-24 00:21:10.055451 | 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) 2026-01-24 00:21:10.055471 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2026-01-24 00:21:10.055492 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2026-01-24 00:21:10.539238 | controller | changed 2026-01-24 00:21:10.553915 | 2026-01-24 00:21:10.554106 | TASK [Set selinux package] 2026-01-24 00:21:10.596175 | controller | ok 2026-01-24 00:21:10.608903 | 2026-01-24 00:21:10.609060 | TASK [Set selinux package (Fedora)] 2026-01-24 00:21:10.656798 | controller | ok 2026-01-24 00:21:10.668618 | 2026-01-24 00:21:10.668904 | TASK [Install selinux into virtualenv] 2026-01-24 00:21:13.559849 | controller | Collecting selinux-please-lie-to-me 2026-01-24 00:21:13.634992 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2026-01-24 00:21:14.148811 | controller | Collecting setuptools<50.0.0 2026-01-24 00:21:14.154812 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2026-01-24 00:21:14.214218 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 14.5 MB/s eta 0:00:00 2026-01-24 00:21:14.372642 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2026-01-24 00:21:14.372952 | controller | Attempting uninstall: setuptools 2026-01-24 00:21:14.376950 | controller | Found existing installation: setuptools 62.6.0 2026-01-24 00:21:14.472408 | controller | Uninstalling setuptools-62.6.0: 2026-01-24 00:21:14.488426 | controller | Successfully uninstalled setuptools-62.6.0 2026-01-24 00:21:15.231551 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2026-01-24 00:21:15.413484 | controller | 2026-01-24 00:21:15.680654 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2026-01-24 00:21:15.680705 | controller | [notice] To update, run: python -m pip install --upgrade pip 2026-01-24 00:21:16.065152 | controller | ok: Runtime: 0:00:04.218762 2026-01-24 00:21:16.078346 | 2026-01-24 00:21:16.078480 | TASK [Install pytest-forked into virtualenv] 2026-01-24 00:21:17.586406 | controller | Collecting pytest-forked 2026-01-24 00:21:17.737580 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2026-01-24 00:21:17.795374 | controller | Collecting py 2026-01-24 00:21:17.801277 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2026-01-24 00:21:17.835467 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.0 MB/s eta 0:00:00 2026-01-24 00:21:18.002389 | controller | Collecting pytest>=3.10 2026-01-24 00:21:18.006952 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2026-01-24 00:21:18.028688 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 20.1 MB/s eta 0:00:00 2026-01-24 00:21:18.079521 | controller | Collecting iniconfig>=1.0.1 2026-01-24 00:21:18.084300 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2026-01-24 00:21:18.151974 | controller | Collecting packaging>=22 2026-01-24 00:21:18.156218 | controller | Downloading packaging-26.0-py3-none-any.whl (74 kB) 2026-01-24 00:21:18.169187 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 74.4/74.4 kB 6.6 MB/s eta 0:00:00 2026-01-24 00:21:18.222296 | controller | Collecting pluggy<2,>=1.5 2026-01-24 00:21:18.226785 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2026-01-24 00:21:18.314022 | controller | Collecting pygments>=2.7.2 2026-01-24 00:21:18.318881 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2026-01-24 00:21:18.349010 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 50.4 MB/s eta 0:00:00 2026-01-24 00:21:18.510234 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2026-01-24 00:21:21.075172 | controller | Successfully installed iniconfig-2.3.0 packaging-26.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0 2026-01-24 00:21:21.093513 | controller | 2026-01-24 00:21:21.324149 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2026-01-24 00:21:21.324200 | controller | [notice] To update, run: python -m pip install --upgrade pip 2026-01-24 00:21:21.484011 | controller | ok: Runtime: 0:00:04.438972 2026-01-24 00:21:21.497550 | 2026-01-24 00:21:21.497739 | TASK [Update pip] 2026-01-24 00:21:22.912845 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2026-01-24 00:21:23.191878 | controller | Collecting pip 2026-01-24 00:21:23.285670 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2026-01-24 00:21:23.384646 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 19.0 MB/s eta 0:00:00 2026-01-24 00:21:23.524867 | controller | Installing collected packages: pip 2026-01-24 00:21:23.525637 | controller | Attempting uninstall: pip 2026-01-24 00:21:23.535094 | controller | Found existing installation: pip 22.2.2 2026-01-24 00:21:23.807016 | controller | Uninstalling pip-22.2.2: 2026-01-24 00:21:23.837520 | controller | Successfully uninstalled pip-22.2.2 2026-01-24 00:21:25.729541 | controller | Successfully installed pip-25.3 2026-01-24 00:21:26.404379 | controller | ok: Runtime: 0:00:03.577737 2026-01-24 00:21:26.416823 | 2026-01-24 00:21:26.417087 | TASK [Ensure pip temp directory exists in /var/tmp] 2026-01-24 00:21:27.349471 | controller | changed 2026-01-24 00:21:27.363143 | 2026-01-24 00:21:27.363330 | TASK [Install ansible into virtualenv] 2026-01-24 00:21:28.662443 | controller | Processing ./src/github.com/ansible/ansible 2026-01-24 00:21:28.667660 | controller | Installing build dependencies: started 2026-01-24 00:21:30.641935 | controller | Installing build dependencies: finished with status 'done' 2026-01-24 00:21:32.212019 | controller | Getting requirements to build wheel: started 2026-01-24 00:21:32.212990 | controller | Getting requirements to build wheel: finished with status 'done' 2026-01-24 00:21:32.213391 | controller | Preparing metadata (pyproject.toml): started 2026-01-24 00:21:33.137602 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2026-01-24 00:21:33.143787 | 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. 2026-01-24 00:21:33.149096 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2026-01-24 00:21:33.760196 | controller | ERROR 2026-01-24 00:21:33.760546 | controller | { 2026-01-24 00:21:33.760610 | controller | "delta": "0:00:05.279915", 2026-01-24 00:21:33.760653 | controller | "end": "2026-01-24 00:21:33.354171", 2026-01-24 00:21:33.760737 | controller | "msg": "non-zero return code", 2026-01-24 00:21:33.760797 | controller | "rc": 1, 2026-01-24 00:21:33.760834 | controller | "start": "2026-01-24 00:21:28.074256" 2026-01-24 00:21:33.760868 | controller | } failure 2026-01-24 00:21:33.763563 | 2026-01-24 00:21:33.763736 | PLAY RECAP 2026-01-24 00:21:33.763839 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2026-01-24 00:21:33.763883 | 2026-01-24 00:21:33.918532 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2026-01-24 00:21:33.920632 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2026-01-24 00:21:34.626350 | 2026-01-24 00:21:34.626492 | PLAY [all] 2026-01-24 00:21:34.649832 | 2026-01-24 00:21:34.649994 | TASK [fetch-subunit-output : Find stestr or testr executable] 2026-01-24 00:21:36.517851 | controller | changed: non-zero return code 2026-01-24 00:21:36.535417 | 2026-01-24 00:21:36.535739 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2026-01-24 00:21:36.566897 | controller | skipping: Conditional result was False 2026-01-24 00:21:36.581943 | 2026-01-24 00:21:36.582186 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2026-01-24 00:21:36.622969 | 2026-01-24 00:21:36.623323 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2026-01-24 00:21:36.681019 | 2026-01-24 00:21:36.681436 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2026-01-24 00:21:36.711652 | controller | skipping: Conditional result was False 2026-01-24 00:21:36.728418 | 2026-01-24 00:21:36.728740 | LOOP [fetch-subunit-output : Generate subunit file] 2026-01-24 00:21:36.774815 | 2026-01-24 00:21:36.775224 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2026-01-24 00:21:36.793920 | controller | skipping: Conditional result was False 2026-01-24 00:21:36.801322 | 2026-01-24 00:21:36.801413 | TASK [fetch-subunit-output : Remove the temporary file] 2026-01-24 00:21:36.817579 | controller | skipping: Conditional result was False 2026-01-24 00:21:36.831182 | 2026-01-24 00:21:36.831333 | TASK [fetch-subunit-output : Process and fetch subunit results] 2026-01-24 00:21:36.858263 | controller | skipping: Conditional result was False 2026-01-24 00:21:36.896836 | 2026-01-24 00:21:36.896930 | PLAY RECAP 2026-01-24 00:21:36.896996 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2026-01-24 00:21:36.897036 | 2026-01-24 00:21:37.078720 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2026-01-24 00:21:37.080129 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2026-01-24 00:21:37.818826 | 2026-01-24 00:21:37.818964 | PLAY [all:!appliance*] 2026-01-24 00:21:37.841234 | 2026-01-24 00:21:37.841346 | TASK [unregister the node] 2026-01-24 00:21:38.192937 | controller | skipping: Conditional result was False 2026-01-24 00:21:38.205969 | 2026-01-24 00:21:38.206130 | TASK [include_role : fetch-output] 2026-01-24 00:21:38.257044 | controller | ok 2026-01-24 00:21:38.303780 | 2026-01-24 00:21:38.303899 | TASK [fetch-output : Set log path for multiple nodes] 2026-01-24 00:21:38.381658 | controller | skipping: Conditional result was False 2026-01-24 00:21:38.396562 | 2026-01-24 00:21:38.396853 | TASK [fetch-output : Set log path for single node] 2026-01-24 00:21:38.447507 | controller | ok 2026-01-24 00:21:38.459482 | 2026-01-24 00:21:38.459634 | LOOP [fetch-output : Ensure local output dirs] 2026-01-24 00:21:38.943293 | controller -> localhost | ok: "/var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/work/logs" 2026-01-24 00:21:39.258100 | controller -> localhost | changed: "/var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/work/artifacts" 2026-01-24 00:21:39.570794 | controller -> localhost | changed: "/var/lib/zuul/builds/3f48a7518deb487598bf25a2206d068c/work/docs" 2026-01-24 00:21:39.581066 | 2026-01-24 00:21:39.581208 | LOOP [fetch-output : Collect logs, artifacts and docs] 2026-01-24 00:21:41.853686 | controller | changed: 2026-01-24 00:21:41.854029 | controller | .d..t...... ./ 2026-01-24 00:21:41.854096 | controller | cd+++++++++ controller/ 2026-01-24 00:21:41.854168 | controller | changed: All items complete 2026-01-24 00:21:41.854215 | 2026-01-24 00:21:43.977207 | controller | changed: .d..t...... ./ 2026-01-24 00:21:46.076850 | controller | changed: .d..t...... ./ 2026-01-24 00:21:46.090171 | 2026-01-24 00:21:46.090308 | TASK [include_role : fetch-output-openshift] 2026-01-24 00:21:46.115642 | controller | skipping: Conditional result was False 2026-01-24 00:21:46.123068 | 2026-01-24 00:21:46.123142 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2026-01-24 00:21:46.167446 | controller | skipping: Conditional result was False 2026-01-24 00:21:46.177991 | controller | skipping: Conditional result was False 2026-01-24 00:21:46.228059 | 2026-01-24 00:21:46.228206 | PLAY [localhost] 2026-01-24 00:21:46.246716 | 2026-01-24 00:21:46.246824 | TASK [Run Zuul manifest role] 2026-01-24 00:21:46.270425 | localhost | ok 2026-01-24 00:21:46.289936 | 2026-01-24 00:21:46.290066 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2026-01-24 00:21:46.761725 | localhost | changed 2026-01-24 00:21:46.769145 | 2026-01-24 00:21:46.769287 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2026-01-24 00:21:46.815015 | localhost | ok 2026-01-24 00:21:46.830821 | 2026-01-24 00:21:46.830931 | TASK [Set zuul-log-path fact] 2026-01-24 00:21:46.886151 | localhost | ok 2026-01-24 00:21:46.899803 | 2026-01-24 00:21:46.899881 | TASK [set-zuul-log-path-fact : Set log path for a build] 2026-01-24 00:21:46.940717 | localhost | ok 2026-01-24 00:21:46.951760 | 2026-01-24 00:21:46.951842 | LOOP [Run upload-logs-swift role] 2026-01-24 00:21:46.998064 | localhost | Output suppressed because no_log was given 2026-01-24 00:21:47.036303 | 2026-01-24 00:21:47.036548 | TASK [Set zuul-log-path fact] 2026-01-24 00:21:47.074797 | localhost | skipping: Conditional result was False 2026-01-24 00:21:47.082809 | 2026-01-24 00:21:47.082931 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2026-01-24 00:21:47.538654 | localhost -> localhost | ok: Runtime: 0:00:00.007415 2026-01-24 00:21:47.550717 | 2026-01-24 00:21:47.550874 | TASK [upload-logs-swift : Upload logs to swift]