2025-12-23 00:22:10.216618 | Job console starting... 2025-12-23 00:22:10.224363 | Updating repositories 2025-12-23 00:22:10.337104 | Preparing job workspace 2025-12-23 00:22:14.122303 | Running Ansible setup... 2025-12-23 00:22:22.436152 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-23 00:22:23.083944 | 2025-12-23 00:22:23.084094 | PLAY [localhost] 2025-12-23 00:22:23.093142 | 2025-12-23 00:22:23.093226 | TASK [Gathering Facts] 2025-12-23 00:22:24.080613 | localhost | ok 2025-12-23 00:22:24.110906 | 2025-12-23 00:22:24.111103 | TASK [Setup log path fact] 2025-12-23 00:22:24.132748 | localhost | ok 2025-12-23 00:22:24.152152 | 2025-12-23 00:22:24.152306 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-23 00:22:24.184306 | localhost | ok 2025-12-23 00:22:24.196666 | 2025-12-23 00:22:24.196807 | TASK [emit-job-header : Print job information] 2025-12-23 00:22:24.258362 | # Job Information 2025-12-23 00:22:24.258535 | Ansible Version: 2.15.12 2025-12-23 00:22:24.258571 | Job: ansible-test-sanity-docker-milestone 2025-12-23 00:22:24.258592 | Pipeline: periodic 2025-12-23 00:22:24.258611 | Executor: ze01.softwarefactory-project.io 2025-12-23 00:22:24.258650 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-23 00:22:24.258692 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/218/ansible/218ef1725aa14bb8a031c4a7e8e6dded/ 2025-12-23 00:22:24.258721 | Event ID: 53716c5a236c4d5eab91d4bd51d64c9b 2025-12-23 00:22:24.262790 | 2025-12-23 00:22:24.262854 | LOOP [emit-job-header : Print node information] 2025-12-23 00:22:24.366258 | localhost | ok: 2025-12-23 00:22:24.366534 | localhost | # Node Information 2025-12-23 00:22:24.366583 | localhost | Inventory Hostname: controller 2025-12-23 00:22:24.366618 | localhost | Hostname: np0005569187 2025-12-23 00:22:24.366652 | localhost | Username: zuul 2025-12-23 00:22:24.366689 | localhost | Distro: Fedora 37 2025-12-23 00:22:24.366722 | localhost | Provider: ansible-vexxhost-ams1 2025-12-23 00:22:24.366755 | localhost | Region: ams1 2025-12-23 00:22:24.366786 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-23 00:22:24.366818 | localhost | Product Name: OpenStack Nova 2025-12-23 00:22:24.366850 | localhost | Interface IP: 38.129.16.138 2025-12-23 00:22:24.378270 | 2025-12-23 00:22:24.378403 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-23 00:22:24.799314 | localhost -> localhost | changed 2025-12-23 00:22:24.805844 | 2025-12-23 00:22:24.805954 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-23 00:22:25.746893 | localhost -> localhost | changed 2025-12-23 00:22:25.792715 | 2025-12-23 00:22:25.792925 | PLAY [all:!appliance*] 2025-12-23 00:22:25.831591 | 2025-12-23 00:22:25.831817 | TASK [include_role : start-zuul-console] 2025-12-23 00:22:25.869754 | controller | ok 2025-12-23 00:22:25.885386 | 2025-12-23 00:22:25.885468 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-23 00:22:26.987262 | controller | ok 2025-12-23 00:22:26.998691 | 2025-12-23 00:22:26.998773 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-23 00:22:29.307027 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-23 00:22:29.313879 | 2025-12-23 00:22:29.313952 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-23 00:22:29.675376 | controller | skipping: Conditional result was False 2025-12-23 00:22:29.689247 | 2025-12-23 00:22:29.689407 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-23 00:22:29.715808 | controller | skipping: Conditional result was False 2025-12-23 00:22:29.728917 | 2025-12-23 00:22:29.729082 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-23 00:22:29.755481 | controller | skipping: Conditional result was False 2025-12-23 00:22:29.769294 | 2025-12-23 00:22:29.769429 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-23 00:22:29.786298 | controller | skipping: Conditional result was False 2025-12-23 00:22:29.802196 | 2025-12-23 00:22:29.802417 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-23 00:22:29.830331 | controller | skipping: Conditional result was False 2025-12-23 00:22:29.850675 | 2025-12-23 00:22:29.850882 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-23 00:22:29.878986 | controller | skipping: Conditional result was False 2025-12-23 00:22:29.894903 | 2025-12-23 00:22:29.895004 | TASK [Disable Fedora Modular] 2025-12-23 00:22:31.108256 | controller | changed 2025-12-23 00:22:31.114900 | 2025-12-23 00:22:31.115001 | TASK [Enable EPEL] 2025-12-23 00:22:31.149272 | controller | skipping: Conditional result was False 2025-12-23 00:22:31.160621 | 2025-12-23 00:22:31.160783 | TASK [Register the RHEL node] 2025-12-23 00:22:31.564336 | 2025-12-23 00:22:31.564535 | TASK [Show the subscription-manager status] 2025-12-23 00:22:31.930422 | controller | skipping: Conditional result was False 2025-12-23 00:22:31.938650 | 2025-12-23 00:22:31.938764 | TASK [Enable EPEL on RHEL] 2025-12-23 00:22:32.311419 | controller | skipping: Conditional result was False 2025-12-23 00:22:32.326306 | 2025-12-23 00:22:32.326504 | TASK [Install git and tox] 2025-12-23 00:24:50.181164 | controller | changed 2025-12-23 00:24:50.197214 | 2025-12-23 00:24:50.197419 | TASK [include_role : prepare-workspace] 2025-12-23 00:24:50.238072 | controller | ok 2025-12-23 00:24:50.276857 | 2025-12-23 00:24:50.276971 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-23 00:24:51.131350 | controller | ok 2025-12-23 00:24:51.147682 | 2025-12-23 00:24:51.147823 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-23 00:25:08.244491 | controller | Output suppressed because no_log was given 2025-12-23 00:25:08.258688 | 2025-12-23 00:25:08.258874 | TASK [include_role : prepare-workspace-openshift] 2025-12-23 00:25:08.285795 | controller | skipping: Conditional result was False 2025-12-23 00:25:08.385866 | 2025-12-23 00:25:08.386007 | PLAY [all:!appliance] 2025-12-23 00:25:08.409787 | 2025-12-23 00:25:08.409969 | TASK [Run add-build-sshkey role (RSA)] 2025-12-23 00:25:08.444680 | controller | ok 2025-12-23 00:25:08.472693 | 2025-12-23 00:25:08.472836 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-23 00:25:08.744366 | controller -> localhost | ok 2025-12-23 00:25:08.753045 | 2025-12-23 00:25:08.753174 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-23 00:25:08.786598 | controller | ok 2025-12-23 00:25:08.806690 | controller | included: /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-23 00:25:08.815856 | 2025-12-23 00:25:08.816071 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-23 00:25:09.436282 | controller -> localhost | Generating public/private rsa key pair. 2025-12-23 00:25:09.436456 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/work/218ef1725aa14bb8a031c4a7e8e6dded_id_rsa. 2025-12-23 00:25:09.436493 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/work/218ef1725aa14bb8a031c4a7e8e6dded_id_rsa.pub. 2025-12-23 00:25:09.436514 | controller -> localhost | The key fingerprint is: 2025-12-23 00:25:09.436532 | controller -> localhost | SHA256:FGyFtgEZfHK1iT/LkSHSeflVjXBcdSfjkWXRNfkBkZo zuul-build-sshkey 2025-12-23 00:25:09.436552 | controller -> localhost | The key's randomart image is: 2025-12-23 00:25:09.436570 | controller -> localhost | +---[RSA 2048]----+ 2025-12-23 00:25:09.436587 | controller -> localhost | | .o=.+o .=OB^| 2025-12-23 00:25:09.436605 | controller -> localhost | | +.O+ + ++O*| 2025-12-23 00:25:09.436622 | controller -> localhost | | .**o* o o o| 2025-12-23 00:25:09.436639 | controller -> localhost | | o.+ E . .| 2025-12-23 00:25:09.436656 | controller -> localhost | | S = . | 2025-12-23 00:25:09.436686 | controller -> localhost | | . + | 2025-12-23 00:25:09.436706 | controller -> localhost | | o | 2025-12-23 00:25:09.436735 | controller -> localhost | | | 2025-12-23 00:25:09.436758 | controller -> localhost | | | 2025-12-23 00:25:09.436779 | controller -> localhost | +----[SHA256]-----+ 2025-12-23 00:25:09.436823 | controller -> localhost | ok: Runtime: 0:00:00.191758 2025-12-23 00:25:09.443142 | 2025-12-23 00:25:09.443206 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-23 00:25:09.473825 | controller | ok 2025-12-23 00:25:09.487777 | controller | included: /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-23 00:25:09.500340 | 2025-12-23 00:25:09.500434 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-23 00:25:09.514407 | controller | skipping: Conditional result was False 2025-12-23 00:25:09.521197 | 2025-12-23 00:25:09.521266 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-23 00:25:10.655895 | controller | changed 2025-12-23 00:25:10.662129 | 2025-12-23 00:25:10.662211 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-23 00:25:11.330499 | controller | ok 2025-12-23 00:25:11.339669 | 2025-12-23 00:25:11.339820 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-23 00:25:14.402197 | controller | changed 2025-12-23 00:25:14.417246 | 2025-12-23 00:25:14.417444 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-23 00:25:17.489361 | controller | changed 2025-12-23 00:25:17.502542 | 2025-12-23 00:25:17.502764 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-23 00:25:17.530212 | controller | skipping: Conditional result was False 2025-12-23 00:25:17.545320 | 2025-12-23 00:25:17.545524 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-23 00:25:17.980523 | controller -> localhost | changed 2025-12-23 00:25:17.992892 | 2025-12-23 00:25:17.993034 | TASK [add-build-sshkey : Add back temp key] 2025-12-23 00:25:18.240309 | controller -> localhost | Identity added: /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/work/218ef1725aa14bb8a031c4a7e8e6dded_id_rsa (zuul-build-sshkey) 2025-12-23 00:25:18.240540 | controller -> localhost | ok: Runtime: 0:00:00.009380 2025-12-23 00:25:18.248478 | 2025-12-23 00:25:18.248583 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-23 00:25:19.231740 | controller | ok 2025-12-23 00:25:19.244834 | 2025-12-23 00:25:19.245009 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-23 00:25:19.283708 | controller | skipping: Conditional result was False 2025-12-23 00:25:19.321345 | 2025-12-23 00:25:19.321595 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-23 00:25:19.364229 | controller | ok 2025-12-23 00:25:19.392596 | 2025-12-23 00:25:19.392700 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-23 00:25:19.682537 | controller -> localhost | ok 2025-12-23 00:25:19.689364 | 2025-12-23 00:25:19.689433 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-23 00:25:19.720257 | controller | ok 2025-12-23 00:25:19.731597 | controller | included: /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-23 00:25:19.738274 | 2025-12-23 00:25:19.738366 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-23 00:25:20.090250 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-23 00:25:20.090636 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/work/218ef1725aa14bb8a031c4a7e8e6dded_id_ecdsa. 2025-12-23 00:25:20.090699 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/work/218ef1725aa14bb8a031c4a7e8e6dded_id_ecdsa.pub. 2025-12-23 00:25:20.090761 | controller -> localhost | The key fingerprint is: 2025-12-23 00:25:20.090806 | controller -> localhost | SHA256:7FGAANSQLRYKjqgMvs8gTBbddML+WWrpoGPfOCd0L5s zuul-build-sshkey 2025-12-23 00:25:20.090849 | controller -> localhost | The key's randomart image is: 2025-12-23 00:25:20.090890 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-23 00:25:20.090930 | controller -> localhost | |..=Bo+ o. | 2025-12-23 00:25:20.090969 | controller -> localhost | |=.= =.+ . | 2025-12-23 00:25:20.091009 | controller -> localhost | |=+ o.. . | 2025-12-23 00:25:20.091087 | controller -> localhost | |= . . . o | 2025-12-23 00:25:20.091128 | controller -> localhost | |.= . S | 2025-12-23 00:25:20.091167 | controller -> localhost | |+ . o O . | 2025-12-23 00:25:20.091206 | controller -> localhost | |.+ o = o | 2025-12-23 00:25:20.091244 | controller -> localhost | |. ++ oo+.. | 2025-12-23 00:25:20.091282 | controller -> localhost | | .ooo+Eo | 2025-12-23 00:25:20.091319 | controller -> localhost | +----[SHA256]-----+ 2025-12-23 00:25:20.091430 | controller -> localhost | ok: Runtime: 0:00:00.010964 2025-12-23 00:25:20.107517 | 2025-12-23 00:25:20.107747 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-23 00:25:20.148355 | controller | ok 2025-12-23 00:25:20.165075 | controller | included: /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-23 00:25:20.180905 | 2025-12-23 00:25:20.181080 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-23 00:25:20.206222 | controller | skipping: Conditional result was False 2025-12-23 00:25:20.215198 | 2025-12-23 00:25:20.215293 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-23 00:25:21.192388 | controller | changed 2025-12-23 00:25:21.206290 | 2025-12-23 00:25:21.206474 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-23 00:25:21.945101 | controller | ok 2025-12-23 00:25:21.954564 | 2025-12-23 00:25:21.954689 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-23 00:25:25.047307 | controller | changed 2025-12-23 00:25:25.053414 | 2025-12-23 00:25:25.053525 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-23 00:25:28.120060 | controller | changed 2025-12-23 00:25:28.129803 | 2025-12-23 00:25:28.129939 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-23 00:25:28.165836 | controller | skipping: Conditional result was False 2025-12-23 00:25:28.172579 | 2025-12-23 00:25:28.172701 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-23 00:25:28.413632 | controller -> localhost | changed 2025-12-23 00:25:28.427246 | 2025-12-23 00:25:28.427383 | TASK [add-build-sshkey : Add back temp key] 2025-12-23 00:25:28.703555 | controller -> localhost | Identity added: /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/work/218ef1725aa14bb8a031c4a7e8e6dded_id_ecdsa (zuul-build-sshkey) 2025-12-23 00:25:28.703804 | controller -> localhost | ok: Runtime: 0:00:00.013609 2025-12-23 00:25:28.710591 | 2025-12-23 00:25:28.710680 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-23 00:25:29.410442 | controller | ok 2025-12-23 00:25:29.416086 | 2025-12-23 00:25:29.416177 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-23 00:25:29.441376 | controller | skipping: Conditional result was False 2025-12-23 00:25:29.452898 | 2025-12-23 00:25:29.452977 | TASK [include_role : remove-zuul-sshkey] 2025-12-23 00:25:29.466767 | controller | skipping: Conditional result was False 2025-12-23 00:25:29.475157 | 2025-12-23 00:25:29.475228 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-23 00:25:30.133776 | controller | ok: "logs" 2025-12-23 00:25:30.134264 | controller | ok: All items complete 2025-12-23 00:25:30.134332 | 2025-12-23 00:25:30.742155 | controller | ok: "artifacts" 2025-12-23 00:25:31.397992 | controller | ok: "docs" 2025-12-23 00:25:31.418581 | 2025-12-23 00:25:31.418797 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-23 00:25:32.100884 | controller | changed: "logs" 2025-12-23 00:25:32.719130 | controller | changed: "artifacts" 2025-12-23 00:25:33.379450 | controller | changed: "docs" 2025-12-23 00:25:33.439449 | 2025-12-23 00:25:33.439578 | PLAY RECAP 2025-12-23 00:25:33.439637 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-23 00:25:33.439675 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-23 00:25:33.439701 | 2025-12-23 00:25:33.592743 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-23 00:25:33.594449 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-23 00:25:34.197078 | 2025-12-23 00:25:34.197201 | PLAY [all] 2025-12-23 00:25:34.220787 | 2025-12-23 00:25:34.220929 | TASK [Install binary dependencies] 2025-12-23 00:25:34.292031 | controller | ok 2025-12-23 00:25:34.315965 | 2025-12-23 00:25:34.316137 | TASK [bindep : Include find tasks] 2025-12-23 00:25:34.359085 | controller | ok 2025-12-23 00:25:34.370260 | controller | included: /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-23 00:25:34.378928 | 2025-12-23 00:25:34.379034 | TASK [bindep : Look for bindep.txt] 2025-12-23 00:25:35.352007 | controller | ok 2025-12-23 00:25:35.363651 | 2025-12-23 00:25:35.363770 | TASK [bindep : Define bindep_file fact] 2025-12-23 00:25:35.400156 | controller | skipping: Conditional result was False 2025-12-23 00:25:35.410474 | 2025-12-23 00:25:35.410656 | TASK [bindep : Look for other-requirements.txt] 2025-12-23 00:25:36.072629 | controller | ok 2025-12-23 00:25:36.083898 | 2025-12-23 00:25:36.084134 | TASK [bindep : Define bindep_file fact] 2025-12-23 00:25:36.109573 | controller | skipping: Conditional result was False 2025-12-23 00:25:36.115968 | 2025-12-23 00:25:36.116115 | TASK [bindep : Look for bindep fallback file] 2025-12-23 00:25:36.140332 | controller | skipping: Conditional result was False 2025-12-23 00:25:36.149391 | 2025-12-23 00:25:36.149549 | TASK [bindep : Define bindep_file fact] 2025-12-23 00:25:36.174640 | controller | skipping: Conditional result was False 2025-12-23 00:25:36.184766 | 2025-12-23 00:25:36.184906 | TASK [bindep : Include bindep tasks] 2025-12-23 00:25:36.209834 | controller | skipping: Conditional result was False 2025-12-23 00:25:36.225376 | 2025-12-23 00:25:36.225548 | TASK [bindep : Include install tasks] 2025-12-23 00:25:36.252536 | controller | skipping: Conditional result was False 2025-12-23 00:25:36.263079 | 2025-12-23 00:25:36.263244 | LOOP [bindep : Include package tasks] 2025-12-23 00:25:36.336115 | 2025-12-23 00:25:36.336301 | TASK [Run test-setup role] 2025-12-23 00:25:36.356444 | controller | ok 2025-12-23 00:25:36.377839 | 2025-12-23 00:25:36.377970 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-23 00:25:37.087714 | controller | ok 2025-12-23 00:25:37.103060 | 2025-12-23 00:25:37.103241 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-23 00:25:37.482380 | controller | skipping: Conditional result was False 2025-12-23 00:25:37.527284 | 2025-12-23 00:25:37.527388 | PLAY RECAP 2025-12-23 00:25:37.527431 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-23 00:25:37.527459 | 2025-12-23 00:25:37.645412 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-23 00:25:37.646322 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-23 00:25:38.285941 | 2025-12-23 00:25:38.286139 | PLAY [controller] 2025-12-23 00:25:38.307823 | 2025-12-23 00:25:38.307978 | TASK [Create the /root directory] 2025-12-23 00:25:39.346533 | controller | ok 2025-12-23 00:25:39.357278 | 2025-12-23 00:25:39.357389 | TASK [Install glibc-langpack-en] 2025-12-23 00:25:47.190754 | controller | ok: Nothing to do 2025-12-23 00:25:47.214011 | 2025-12-23 00:25:47.214238 | TASK [Ensure controller directory exists] 2025-12-23 00:25:48.073426 | controller | changed 2025-12-23 00:25:48.086225 | 2025-12-23 00:25:48.086406 | TASK [Install container runtime] 2025-12-23 00:25:48.134995 | controller | ok 2025-12-23 00:25:48.194600 | 2025-12-23 00:25:48.194746 | LOOP [ensure-podman : Find distribution installation] 2025-12-23 00:25:48.220758 | controller | ok: "/var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-23 00:25:48.240977 | controller | included: /var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-23 00:25:48.250384 | 2025-12-23 00:25:48.250487 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-23 00:27:46.381227 | controller | changed 2025-12-23 00:27:46.389804 | 2025-12-23 00:27:46.389922 | TASK [ensure-podman : Fetch podman version] 2025-12-23 00:27:47.499455 | controller | Client: Podman Engine 2025-12-23 00:27:47.535145 | controller | Version: 4.6.2 2025-12-23 00:27:47.535206 | controller | API Version: 4.6.2 2025-12-23 00:27:47.535214 | controller | Go Version: go1.19.12 2025-12-23 00:27:47.535237 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-23 00:27:47.535246 | controller | OS/Arch: linux/amd64 2025-12-23 00:27:47.746101 | controller | ok: Runtime: 0:00:00.257445 2025-12-23 00:27:47.759394 | 2025-12-23 00:27:47.759554 | TASK [ensure-podman : Print podman version installed] 2025-12-23 00:27:47.799264 | Podman version: Client: Podman Engine 2025-12-23 00:27:47.799539 | Version: 4.6.2 2025-12-23 00:27:47.799598 | API Version: 4.6.2 2025-12-23 00:27:47.799641 | Go Version: go1.19.12 2025-12-23 00:27:47.799679 | Built: Mon Aug 28 19:38:31 2023 2025-12-23 00:27:47.799720 | OS/Arch: linux/amd64 2025-12-23 00:27:47.812393 | 2025-12-23 00:27:47.812595 | TASK [ensure-podman : Validate podman engine] 2025-12-23 00:27:48.178006 | controller | skipping: Conditional result was False 2025-12-23 00:27:48.186966 | 2025-12-23 00:27:48.187084 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-23 00:27:48.212356 | controller | skipping: Conditional result was False 2025-12-23 00:27:48.229627 | 2025-12-23 00:27:48.229767 | TASK [Ensure python3.8 is present] 2025-12-23 00:27:48.255870 | controller | skipping: Conditional result was False 2025-12-23 00:27:48.264946 | 2025-12-23 00:27:48.265085 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-23 00:27:48.289790 | controller | ok 2025-12-23 00:27:48.319546 | 2025-12-23 00:27:48.319685 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-23 00:27:52.137630 | controller | ok: Nothing to do 2025-12-23 00:27:52.150615 | 2025-12-23 00:27:52.150792 | TASK [our-ensure-python : Also install python3-devel] 2025-12-23 00:28:07.097908 | controller | changed 2025-12-23 00:28:07.108700 | 2025-12-23 00:28:07.108778 | TASK [Run ensure-virtualenv role] 2025-12-23 00:28:07.129601 | controller | ok 2025-12-23 00:28:07.180342 | 2025-12-23 00:28:07.180466 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-23 00:28:07.956405 | controller | /usr/bin/virtualenv 2025-12-23 00:28:08.563254 | controller | ok: Runtime: 0:00:00.011623 2025-12-23 00:28:08.571439 | 2025-12-23 00:28:08.571545 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-23 00:28:08.608128 | controller | skipping: Conditional result was False 2025-12-23 00:28:08.608642 | controller | ok: All items complete 2025-12-23 00:28:08.608701 | 2025-12-23 00:28:08.631376 | 2025-12-23 00:28:08.631519 | TASK [Find the full path of the Python interpreter] 2025-12-23 00:28:09.519092 | controller | /usr/bin/python3 2025-12-23 00:28:09.998839 | controller | ok 2025-12-23 00:28:10.023836 | 2025-12-23 00:28:10.024048 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-23 00:28:11.967095 | controller | created virtual environment CPython3.11.0.final.0-64 in 943ms 2025-12-23 00:28:12.087104 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-23 00:28:12.088036 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv) 2025-12-23 00:28:12.088060 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-23 00:28:12.088083 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-23 00:28:12.413715 | controller | changed 2025-12-23 00:28:12.428211 | 2025-12-23 00:28:12.428412 | TASK [Set selinux package] 2025-12-23 00:28:12.471204 | controller | ok 2025-12-23 00:28:12.484607 | 2025-12-23 00:28:12.484748 | TASK [Set selinux package (Fedora)] 2025-12-23 00:28:12.545109 | controller | ok 2025-12-23 00:28:12.557498 | 2025-12-23 00:28:12.557645 | TASK [Install selinux into virtualenv] 2025-12-23 00:28:15.577469 | controller | Collecting selinux-please-lie-to-me 2025-12-23 00:28:15.638705 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-23 00:28:16.171376 | controller | Collecting setuptools<50.0.0 2025-12-23 00:28:16.196497 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-23 00:28:16.257395 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 15.7 MB/s eta 0:00:00 2025-12-23 00:28:16.439020 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-23 00:28:16.439464 | controller | Attempting uninstall: setuptools 2025-12-23 00:28:16.445486 | controller | Found existing installation: setuptools 62.6.0 2025-12-23 00:28:16.549146 | controller | Uninstalling setuptools-62.6.0: 2025-12-23 00:28:16.565133 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-23 00:28:17.478773 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-23 00:28:17.730000 | controller | 2025-12-23 00:28:18.246405 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-23 00:28:18.246454 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-23 00:28:18.473423 | controller | ok: Runtime: 0:00:04.887677 2025-12-23 00:28:18.479239 | 2025-12-23 00:28:18.479329 | TASK [Install pytest-forked into virtualenv] 2025-12-23 00:28:20.054977 | controller | Collecting pytest-forked 2025-12-23 00:28:20.114425 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-23 00:28:20.194754 | controller | Collecting py 2025-12-23 00:28:20.201560 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-23 00:28:20.230486 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.2 MB/s eta 0:00:00 2025-12-23 00:28:20.425457 | controller | Collecting pytest>=3.10 2025-12-23 00:28:20.435550 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-23 00:28:20.462619 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 17.1 MB/s eta 0:00:00 2025-12-23 00:28:20.534255 | controller | Collecting iniconfig>=1.0.1 2025-12-23 00:28:20.544040 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-23 00:28:20.627446 | controller | Collecting packaging>=22 2025-12-23 00:28:20.633195 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-23 00:28:20.648636 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.9 MB/s eta 0:00:00 2025-12-23 00:28:20.710668 | controller | Collecting pluggy<2,>=1.5 2025-12-23 00:28:20.719719 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-23 00:28:20.813921 | controller | Collecting pygments>=2.7.2 2025-12-23 00:28:20.819357 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-23 00:28:20.863336 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 31.7 MB/s eta 0:00:00 2025-12-23 00:28:21.051319 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-23 00:28:23.524510 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0 2025-12-23 00:28:23.539070 | controller | 2025-12-23 00:28:23.925036 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-23 00:28:23.925103 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-23 00:28:24.366158 | controller | ok: Runtime: 0:00:04.658332 2025-12-23 00:28:24.379975 | 2025-12-23 00:28:24.380172 | TASK [Update pip] 2025-12-23 00:28:25.708169 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-23 00:28:25.960715 | controller | Collecting pip 2025-12-23 00:28:26.039800 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-23 00:28:26.111770 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 26.6 MB/s eta 0:00:00 2025-12-23 00:28:26.230509 | controller | Installing collected packages: pip 2025-12-23 00:28:26.232958 | controller | Attempting uninstall: pip 2025-12-23 00:28:26.238383 | controller | Found existing installation: pip 22.2.2 2025-12-23 00:28:26.539433 | controller | Uninstalling pip-22.2.2: 2025-12-23 00:28:26.568475 | controller | Successfully uninstalled pip-22.2.2 2025-12-23 00:28:28.510017 | controller | Successfully installed pip-25.3 2025-12-23 00:28:29.286486 | controller | ok: Runtime: 0:00:03.696461 2025-12-23 00:28:29.294678 | 2025-12-23 00:28:29.294792 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-23 00:28:30.353114 | controller | changed 2025-12-23 00:28:30.361806 | 2025-12-23 00:28:30.361865 | TASK [Install ansible into virtualenv] 2025-12-23 00:28:31.865764 | controller | Processing ./src/github.com/ansible/ansible 2025-12-23 00:28:31.871031 | controller | Installing build dependencies: started 2025-12-23 00:28:33.941462 | controller | Installing build dependencies: finished with status 'done' 2025-12-23 00:28:33.942616 | controller | Getting requirements to build wheel: started 2025-12-23 00:28:35.466838 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-23 00:28:35.469538 | controller | Preparing metadata (pyproject.toml): started 2025-12-23 00:28:36.268506 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-23 00:28:36.272458 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-12-23 00:28:36.276186 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-23 00:28:36.749831 | controller | ERROR 2025-12-23 00:28:36.750425 | controller | { 2025-12-23 00:28:36.750502 | controller | "delta": "0:00:05.267818", 2025-12-23 00:28:36.751274 | controller | "end": "2025-12-23 00:28:36.423251", 2025-12-23 00:28:36.751340 | controller | "msg": "non-zero return code", 2025-12-23 00:28:36.751416 | controller | "rc": 1, 2025-12-23 00:28:36.751454 | controller | "start": "2025-12-23 00:28:31.155433" 2025-12-23 00:28:36.751489 | controller | } failure 2025-12-23 00:28:36.755624 | 2025-12-23 00:28:36.755791 | PLAY RECAP 2025-12-23 00:28:36.755902 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-23 00:28:36.755958 | 2025-12-23 00:28:36.949619 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-23 00:28:36.952248 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-23 00:28:37.568477 | 2025-12-23 00:28:37.568599 | PLAY [all] 2025-12-23 00:28:37.591652 | 2025-12-23 00:28:37.591776 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-23 00:28:39.433155 | controller | changed: non-zero return code 2025-12-23 00:28:39.441270 | 2025-12-23 00:28:39.441385 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-23 00:28:39.467400 | controller | skipping: Conditional result was False 2025-12-23 00:28:39.475678 | 2025-12-23 00:28:39.475780 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-23 00:28:39.521359 | 2025-12-23 00:28:39.521555 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-23 00:28:39.557433 | 2025-12-23 00:28:39.557634 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-23 00:28:39.583710 | controller | skipping: Conditional result was False 2025-12-23 00:28:39.590511 | 2025-12-23 00:28:39.590588 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-23 00:28:39.620490 | 2025-12-23 00:28:39.620627 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-23 00:28:39.644459 | controller | skipping: Conditional result was False 2025-12-23 00:28:39.650319 | 2025-12-23 00:28:39.650385 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-23 00:28:39.674046 | controller | skipping: Conditional result was False 2025-12-23 00:28:39.679858 | 2025-12-23 00:28:39.679986 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-23 00:28:39.703688 | controller | skipping: Conditional result was False 2025-12-23 00:28:39.733298 | 2025-12-23 00:28:39.733411 | PLAY RECAP 2025-12-23 00:28:39.733457 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-23 00:28:39.733477 | 2025-12-23 00:28:39.846526 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-23 00:28:39.848270 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-23 00:28:40.396702 | 2025-12-23 00:28:40.396810 | PLAY [all:!appliance*] 2025-12-23 00:28:40.417746 | 2025-12-23 00:28:40.417838 | TASK [unregister the node] 2025-12-23 00:28:40.773322 | controller | skipping: Conditional result was False 2025-12-23 00:28:40.785303 | 2025-12-23 00:28:40.785467 | TASK [include_role : fetch-output] 2025-12-23 00:28:40.835626 | controller | ok 2025-12-23 00:28:40.877589 | 2025-12-23 00:28:40.877719 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-23 00:28:40.953221 | controller | skipping: Conditional result was False 2025-12-23 00:28:40.965471 | 2025-12-23 00:28:40.965607 | TASK [fetch-output : Set log path for single node] 2025-12-23 00:28:41.012964 | controller | ok 2025-12-23 00:28:41.026440 | 2025-12-23 00:28:41.026662 | LOOP [fetch-output : Ensure local output dirs] 2025-12-23 00:28:41.497031 | controller -> localhost | ok: "/var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/work/logs" 2025-12-23 00:28:41.739800 | controller -> localhost | changed: "/var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/work/artifacts" 2025-12-23 00:28:41.959173 | controller -> localhost | changed: "/var/lib/zuul/builds/218ef1725aa14bb8a031c4a7e8e6dded/work/docs" 2025-12-23 00:28:41.972872 | 2025-12-23 00:28:41.973114 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-23 00:28:44.248426 | controller | changed: 2025-12-23 00:28:44.248743 | controller | .d..t...... ./ 2025-12-23 00:28:44.248803 | controller | cd+++++++++ controller/ 2025-12-23 00:28:44.248876 | controller | changed: All items complete 2025-12-23 00:28:44.248919 | 2025-12-23 00:28:46.302312 | controller | changed: .d..t...... ./ 2025-12-23 00:28:48.384192 | controller | changed: .d..t...... ./ 2025-12-23 00:28:48.417401 | 2025-12-23 00:28:48.417592 | TASK [include_role : fetch-output-openshift] 2025-12-23 00:28:48.445539 | controller | skipping: Conditional result was False 2025-12-23 00:28:48.460456 | 2025-12-23 00:28:48.460728 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-23 00:28:48.488300 | controller | skipping: Conditional result was False 2025-12-23 00:28:48.495322 | controller | skipping: Conditional result was False 2025-12-23 00:28:48.538221 | 2025-12-23 00:28:48.538377 | PLAY [localhost] 2025-12-23 00:28:48.556127 | 2025-12-23 00:28:48.556212 | TASK [Run Zuul manifest role] 2025-12-23 00:28:48.576676 | localhost | ok 2025-12-23 00:28:48.596232 | 2025-12-23 00:28:48.596328 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-23 00:28:48.961043 | localhost | changed 2025-12-23 00:28:48.965483 | 2025-12-23 00:28:48.965543 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-23 00:28:49.015161 | localhost | ok 2025-12-23 00:28:49.027512 | 2025-12-23 00:28:49.027596 | TASK [Set zuul-log-path fact] 2025-12-23 00:28:49.076525 | localhost | ok 2025-12-23 00:28:49.091507 | 2025-12-23 00:28:49.091596 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-23 00:28:49.129758 | localhost | ok 2025-12-23 00:28:49.137623 | 2025-12-23 00:28:49.137769 | LOOP [Run upload-logs-swift role] 2025-12-23 00:28:49.182359 | localhost | Output suppressed because no_log was given 2025-12-23 00:28:49.208118 | 2025-12-23 00:28:49.208225 | TASK [Set zuul-log-path fact] 2025-12-23 00:28:49.252363 | localhost | skipping: Conditional result was False 2025-12-23 00:28:49.262458 | 2025-12-23 00:28:49.262604 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-23 00:28:49.706454 | localhost -> localhost | ok: Runtime: 0:00:00.008521 2025-12-23 00:28:49.717714 | 2025-12-23 00:28:49.717881 | TASK [upload-logs-swift : Upload logs to swift]