2025-12-25 00:06:48.921307 | Job console starting... 2025-12-25 00:06:48.934797 | Updating repositories 2025-12-25 00:06:51.861484 | Preparing job workspace 2025-12-25 00:06:55.843261 | Running Ansible setup... 2025-12-25 00:07:00.454217 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-25 00:07:01.100771 | 2025-12-25 00:07:01.100935 | PLAY [localhost] 2025-12-25 00:07:01.110575 | 2025-12-25 00:07:01.110696 | TASK [Gathering Facts] 2025-12-25 00:07:02.266855 | localhost | ok 2025-12-25 00:07:02.283530 | 2025-12-25 00:07:02.283671 | TASK [Setup log path fact] 2025-12-25 00:07:02.302628 | localhost | ok 2025-12-25 00:07:02.315853 | 2025-12-25 00:07:02.315963 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-25 00:07:02.344443 | localhost | ok 2025-12-25 00:07:02.352273 | 2025-12-25 00:07:02.352344 | TASK [emit-job-header : Print job information] 2025-12-25 00:07:02.391260 | # Job Information 2025-12-25 00:07:02.391582 | Ansible Version: 2.15.12 2025-12-25 00:07:02.391612 | Job: ansible-test-sanity-docker-milestone 2025-12-25 00:07:02.391635 | Pipeline: periodic 2025-12-25 00:07:02.391654 | Executor: ze01.softwarefactory-project.io 2025-12-25 00:07:02.391671 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-25 00:07:02.391692 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/045/ansible/045106d8805542c6a7db161f8c311628/ 2025-12-25 00:07:02.391710 | Event ID: 9bcd164eed0a4284892079c0f800abca 2025-12-25 00:07:02.395927 | 2025-12-25 00:07:02.395996 | LOOP [emit-job-header : Print node information] 2025-12-25 00:07:02.515556 | localhost | ok: 2025-12-25 00:07:02.515744 | localhost | # Node Information 2025-12-25 00:07:02.515771 | localhost | Inventory Hostname: controller 2025-12-25 00:07:02.515791 | localhost | Hostname: np0005570304 2025-12-25 00:07:02.515810 | localhost | Username: zuul 2025-12-25 00:07:02.515831 | localhost | Distro: Fedora 37 2025-12-25 00:07:02.515849 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-25 00:07:02.515866 | localhost | Region: ca-ymq-1 2025-12-25 00:07:02.515883 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-25 00:07:02.515899 | localhost | Product Name: OpenStack Nova 2025-12-25 00:07:02.515915 | localhost | Interface IP: 162.253.55.140 2025-12-25 00:07:02.537714 | 2025-12-25 00:07:02.537884 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-25 00:07:03.087495 | localhost -> localhost | changed 2025-12-25 00:07:03.093501 | 2025-12-25 00:07:03.093602 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-25 00:07:04.061458 | localhost -> localhost | changed 2025-12-25 00:07:04.095065 | 2025-12-25 00:07:04.095259 | PLAY [all:!appliance*] 2025-12-25 00:07:04.122704 | 2025-12-25 00:07:04.122867 | TASK [include_role : start-zuul-console] 2025-12-25 00:07:04.156683 | controller | ok 2025-12-25 00:07:04.177206 | 2025-12-25 00:07:04.177367 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-25 00:07:04.582257 | controller | ok 2025-12-25 00:07:04.600051 | 2025-12-25 00:07:04.600216 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-25 00:07:06.126096 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-25 00:07:06.136999 | 2025-12-25 00:07:06.137177 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-25 00:07:06.684308 | controller | skipping: Conditional result was False 2025-12-25 00:07:06.691689 | 2025-12-25 00:07:06.691822 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-25 00:07:06.716326 | controller | skipping: Conditional result was False 2025-12-25 00:07:06.730828 | 2025-12-25 00:07:06.731539 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-25 00:07:06.781453 | controller | skipping: Conditional result was False 2025-12-25 00:07:06.791178 | 2025-12-25 00:07:06.791471 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-25 00:07:06.819692 | controller | skipping: Conditional result was False 2025-12-25 00:07:06.830643 | 2025-12-25 00:07:06.830822 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-25 00:07:06.855833 | controller | skipping: Conditional result was False 2025-12-25 00:07:06.863351 | 2025-12-25 00:07:06.863468 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-25 00:07:06.887893 | controller | skipping: Conditional result was False 2025-12-25 00:07:06.904294 | 2025-12-25 00:07:06.904421 | TASK [Disable Fedora Modular] 2025-12-25 00:07:07.143403 | controller | changed 2025-12-25 00:07:07.149421 | 2025-12-25 00:07:07.149494 | TASK [Enable EPEL] 2025-12-25 00:07:07.176355 | controller | skipping: Conditional result was False 2025-12-25 00:07:07.183477 | 2025-12-25 00:07:07.183575 | TASK [Register the RHEL node] 2025-12-25 00:07:07.728913 | 2025-12-25 00:07:07.729146 | TASK [Show the subscription-manager status] 2025-12-25 00:07:08.349339 | controller | skipping: Conditional result was False 2025-12-25 00:07:08.359686 | 2025-12-25 00:07:08.359816 | TASK [Enable EPEL on RHEL] 2025-12-25 00:07:08.908914 | controller | skipping: Conditional result was False 2025-12-25 00:07:08.915821 | 2025-12-25 00:07:08.915939 | TASK [Install git and tox] 2025-12-25 00:09:09.176939 | controller | changed 2025-12-25 00:09:09.192097 | 2025-12-25 00:09:09.192247 | TASK [include_role : prepare-workspace] 2025-12-25 00:09:09.215355 | controller | ok 2025-12-25 00:09:09.236382 | 2025-12-25 00:09:09.236498 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-25 00:09:09.451935 | controller | ok 2025-12-25 00:09:09.462048 | 2025-12-25 00:09:09.462146 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-25 00:09:22.962423 | controller | Output suppressed because no_log was given 2025-12-25 00:09:22.991746 | 2025-12-25 00:09:22.991859 | TASK [include_role : prepare-workspace-openshift] 2025-12-25 00:09:23.020598 | controller | skipping: Conditional result was False 2025-12-25 00:09:23.051698 | 2025-12-25 00:09:23.051808 | PLAY [all:!appliance] 2025-12-25 00:09:23.076465 | 2025-12-25 00:09:23.076599 | TASK [Run add-build-sshkey role (RSA)] 2025-12-25 00:09:23.119784 | controller | ok 2025-12-25 00:09:23.140635 | 2025-12-25 00:09:23.140751 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-25 00:09:23.360853 | controller -> localhost | ok 2025-12-25 00:09:23.369501 | 2025-12-25 00:09:23.369590 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-25 00:09:23.392062 | controller | ok 2025-12-25 00:09:23.423906 | controller | included: /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-25 00:09:23.433617 | 2025-12-25 00:09:23.433723 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-25 00:09:23.928174 | controller -> localhost | Generating public/private rsa key pair. 2025-12-25 00:09:23.928578 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/work/045106d8805542c6a7db161f8c311628_id_rsa. 2025-12-25 00:09:23.928644 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/work/045106d8805542c6a7db161f8c311628_id_rsa.pub. 2025-12-25 00:09:23.928751 | controller -> localhost | The key fingerprint is: 2025-12-25 00:09:23.928816 | controller -> localhost | SHA256:x+GXS27q4mhlzYZUSMxVzz978PWxaHFWTFhT5VEXp7g zuul-build-sshkey 2025-12-25 00:09:23.928874 | controller -> localhost | The key's randomart image is: 2025-12-25 00:09:23.928922 | controller -> localhost | +---[RSA 2048]----+ 2025-12-25 00:09:23.928963 | controller -> localhost | | +.o... *&| 2025-12-25 00:09:23.929005 | controller -> localhost | | + . +.==| 2025-12-25 00:09:23.929083 | controller -> localhost | | .. . + +| 2025-12-25 00:09:23.929124 | controller -> localhost | | .o . o ..| 2025-12-25 00:09:23.929162 | controller -> localhost | | .S++ E..=o| 2025-12-25 00:09:23.929222 | controller -> localhost | | +.++ .=oB| 2025-12-25 00:09:23.929270 | controller -> localhost | | o . +o o+| 2025-12-25 00:09:23.929311 | controller -> localhost | | ... o. .| 2025-12-25 00:09:23.929351 | controller -> localhost | | ....oo | 2025-12-25 00:09:23.929395 | controller -> localhost | +----[SHA256]-----+ 2025-12-25 00:09:23.929494 | controller -> localhost | ok: Runtime: 0:00:00.041570 2025-12-25 00:09:23.945942 | 2025-12-25 00:09:23.946146 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-25 00:09:23.979522 | controller | ok 2025-12-25 00:09:23.991869 | controller | included: /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-25 00:09:24.002952 | 2025-12-25 00:09:24.003113 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-25 00:09:24.027892 | controller | skipping: Conditional result was False 2025-12-25 00:09:24.035681 | 2025-12-25 00:09:24.035776 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-25 00:09:24.499768 | controller | changed 2025-12-25 00:09:24.509604 | 2025-12-25 00:09:24.509700 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-25 00:09:24.725358 | controller | ok 2025-12-25 00:09:24.732287 | 2025-12-25 00:09:24.732367 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-25 00:09:25.392426 | controller | changed 2025-12-25 00:09:25.407299 | 2025-12-25 00:09:25.407469 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-25 00:09:26.052694 | controller | changed 2025-12-25 00:09:26.066754 | 2025-12-25 00:09:26.066977 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-25 00:09:26.105057 | controller | skipping: Conditional result was False 2025-12-25 00:09:26.121009 | 2025-12-25 00:09:26.121230 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-25 00:09:26.545573 | controller -> localhost | changed 2025-12-25 00:09:26.561121 | 2025-12-25 00:09:26.561257 | TASK [add-build-sshkey : Add back temp key] 2025-12-25 00:09:26.904820 | controller -> localhost | Identity added: /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/work/045106d8805542c6a7db161f8c311628_id_rsa (zuul-build-sshkey) 2025-12-25 00:09:26.905299 | controller -> localhost | ok: Runtime: 0:00:00.014834 2025-12-25 00:09:26.916826 | 2025-12-25 00:09:26.916993 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-25 00:09:27.349658 | controller | ok 2025-12-25 00:09:27.355794 | 2025-12-25 00:09:27.355874 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-25 00:09:27.381111 | controller | skipping: Conditional result was False 2025-12-25 00:09:27.394828 | 2025-12-25 00:09:27.394952 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-25 00:09:27.414984 | controller | ok 2025-12-25 00:09:27.432119 | 2025-12-25 00:09:27.432211 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-25 00:09:27.651052 | controller -> localhost | ok 2025-12-25 00:09:27.658155 | 2025-12-25 00:09:27.658231 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-25 00:09:27.699943 | controller | ok 2025-12-25 00:09:27.710701 | controller | included: /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-25 00:09:27.716742 | 2025-12-25 00:09:27.716807 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-25 00:09:28.109082 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-25 00:09:28.109291 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/work/045106d8805542c6a7db161f8c311628_id_ecdsa. 2025-12-25 00:09:28.109335 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/work/045106d8805542c6a7db161f8c311628_id_ecdsa.pub. 2025-12-25 00:09:28.109370 | controller -> localhost | The key fingerprint is: 2025-12-25 00:09:28.109390 | controller -> localhost | SHA256:XWqjpnkH0gCn6ByBov138l3ec1+WUalTElURXzilVRQ zuul-build-sshkey 2025-12-25 00:09:28.109435 | controller -> localhost | The key's randomart image is: 2025-12-25 00:09:28.109455 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-25 00:09:28.109473 | controller -> localhost | | . ..E&| 2025-12-25 00:09:28.109490 | controller -> localhost | |o . . . +o+| 2025-12-25 00:09:28.109507 | controller -> localhost | |o. o + ...+o| 2025-12-25 00:09:28.109524 | controller -> localhost | |. + . . . o + .| 2025-12-25 00:09:28.109541 | controller -> localhost | | o o oS = o . | 2025-12-25 00:09:28.109558 | controller -> localhost | | o . + +o .. . o| 2025-12-25 00:09:28.109575 | controller -> localhost | | . =oo o . .o| 2025-12-25 00:09:28.109592 | controller -> localhost | | +o o . o.o| 2025-12-25 00:09:28.109610 | controller -> localhost | | o. . oo| 2025-12-25 00:09:28.109628 | controller -> localhost | +----[SHA256]-----+ 2025-12-25 00:09:28.109675 | controller -> localhost | ok: Runtime: 0:00:00.018658 2025-12-25 00:09:28.117208 | 2025-12-25 00:09:28.117312 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-25 00:09:28.152174 | controller | ok 2025-12-25 00:09:28.164432 | controller | included: /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-25 00:09:28.177198 | 2025-12-25 00:09:28.177305 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-25 00:09:28.203578 | controller | skipping: Conditional result was False 2025-12-25 00:09:28.212088 | 2025-12-25 00:09:28.212274 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-25 00:09:28.491620 | controller | changed 2025-12-25 00:09:28.500392 | 2025-12-25 00:09:28.500508 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-25 00:09:28.718703 | controller | ok 2025-12-25 00:09:28.724694 | 2025-12-25 00:09:28.724761 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-25 00:09:29.369423 | controller | changed 2025-12-25 00:09:29.375176 | 2025-12-25 00:09:29.375270 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-25 00:09:29.995380 | controller | changed 2025-12-25 00:09:30.027493 | 2025-12-25 00:09:30.027614 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-25 00:09:30.051526 | controller | skipping: Conditional result was False 2025-12-25 00:09:30.057858 | 2025-12-25 00:09:30.057924 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-25 00:09:30.275405 | controller -> localhost | changed 2025-12-25 00:09:30.287926 | 2025-12-25 00:09:30.288073 | TASK [add-build-sshkey : Add back temp key] 2025-12-25 00:09:30.556309 | controller -> localhost | Identity added: /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/work/045106d8805542c6a7db161f8c311628_id_ecdsa (zuul-build-sshkey) 2025-12-25 00:09:30.556505 | controller -> localhost | ok: Runtime: 0:00:00.007544 2025-12-25 00:09:30.563178 | 2025-12-25 00:09:30.563242 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-25 00:09:30.787546 | controller | ok 2025-12-25 00:09:30.801073 | 2025-12-25 00:09:30.801251 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-25 00:09:30.828202 | controller | skipping: Conditional result was False 2025-12-25 00:09:30.857323 | 2025-12-25 00:09:30.857512 | TASK [include_role : remove-zuul-sshkey] 2025-12-25 00:09:30.874556 | controller | skipping: Conditional result was False 2025-12-25 00:09:30.885383 | 2025-12-25 00:09:30.885514 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-25 00:09:31.131821 | controller | ok: "logs" 2025-12-25 00:09:31.132172 | controller | ok: All items complete 2025-12-25 00:09:31.132217 | 2025-12-25 00:09:31.330965 | controller | ok: "artifacts" 2025-12-25 00:09:31.509691 | controller | ok: "docs" 2025-12-25 00:09:31.516557 | 2025-12-25 00:09:31.516632 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-25 00:09:31.739995 | controller | changed: "logs" 2025-12-25 00:09:31.927979 | controller | changed: "artifacts" 2025-12-25 00:09:32.162117 | controller | changed: "docs" 2025-12-25 00:09:32.233460 | 2025-12-25 00:09:32.233644 | PLAY RECAP 2025-12-25 00:09:32.233699 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-25 00:09:32.233726 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-25 00:09:32.233744 | 2025-12-25 00:09:32.384589 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-25 00:09:32.385534 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-25 00:09:33.029181 | 2025-12-25 00:09:33.029321 | PLAY [all] 2025-12-25 00:09:33.055458 | 2025-12-25 00:09:33.055592 | TASK [Install binary dependencies] 2025-12-25 00:09:33.106281 | controller | ok 2025-12-25 00:09:33.127799 | 2025-12-25 00:09:33.127965 | TASK [bindep : Include find tasks] 2025-12-25 00:09:33.170739 | controller | ok 2025-12-25 00:09:33.179363 | controller | included: /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-25 00:09:33.186494 | 2025-12-25 00:09:33.186623 | TASK [bindep : Look for bindep.txt] 2025-12-25 00:09:33.524560 | controller | ok 2025-12-25 00:09:33.533101 | 2025-12-25 00:09:33.533255 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:09:33.550198 | controller | skipping: Conditional result was False 2025-12-25 00:09:33.560800 | 2025-12-25 00:09:33.560933 | TASK [bindep : Look for other-requirements.txt] 2025-12-25 00:09:33.774722 | controller | ok 2025-12-25 00:09:33.780896 | 2025-12-25 00:09:33.780964 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:09:33.817395 | controller | skipping: Conditional result was False 2025-12-25 00:09:33.831533 | 2025-12-25 00:09:33.831859 | TASK [bindep : Look for bindep fallback file] 2025-12-25 00:09:33.870764 | controller | skipping: Conditional result was False 2025-12-25 00:09:33.887497 | 2025-12-25 00:09:33.887670 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:09:33.915109 | controller | skipping: Conditional result was False 2025-12-25 00:09:33.930389 | 2025-12-25 00:09:33.930531 | TASK [bindep : Include bindep tasks] 2025-12-25 00:09:33.957639 | controller | skipping: Conditional result was False 2025-12-25 00:09:33.964359 | 2025-12-25 00:09:33.964430 | TASK [bindep : Include install tasks] 2025-12-25 00:09:33.988489 | controller | skipping: Conditional result was False 2025-12-25 00:09:33.994588 | 2025-12-25 00:09:33.994669 | LOOP [bindep : Include package tasks] 2025-12-25 00:09:34.049995 | 2025-12-25 00:09:34.050206 | TASK [Run test-setup role] 2025-12-25 00:09:34.071391 | controller | ok 2025-12-25 00:09:34.089116 | 2025-12-25 00:09:34.089225 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-25 00:09:34.308253 | controller | ok 2025-12-25 00:09:34.341487 | 2025-12-25 00:09:34.341650 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-25 00:09:34.907182 | controller | skipping: Conditional result was False 2025-12-25 00:09:34.959106 | 2025-12-25 00:09:34.959234 | PLAY RECAP 2025-12-25 00:09:34.959289 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-25 00:09:34.959318 | 2025-12-25 00:09:35.081504 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-25 00:09:35.082838 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-25 00:09:35.733402 | 2025-12-25 00:09:35.733530 | PLAY [controller] 2025-12-25 00:09:35.753364 | 2025-12-25 00:09:35.753455 | TASK [Create the /root directory] 2025-12-25 00:09:36.132166 | controller | ok 2025-12-25 00:09:36.138550 | 2025-12-25 00:09:36.138641 | TASK [Install glibc-langpack-en] 2025-12-25 00:09:40.128830 | controller | ok: Nothing to do 2025-12-25 00:09:40.135123 | 2025-12-25 00:09:40.135223 | TASK [Ensure controller directory exists] 2025-12-25 00:09:40.346995 | controller | changed 2025-12-25 00:09:40.361814 | 2025-12-25 00:09:40.362198 | TASK [Install container runtime] 2025-12-25 00:09:40.438647 | controller | ok 2025-12-25 00:09:40.484908 | 2025-12-25 00:09:40.485040 | LOOP [ensure-podman : Find distribution installation] 2025-12-25 00:09:40.507235 | controller | ok: "/var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-25 00:09:40.516184 | controller | included: /var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-25 00:09:40.522611 | 2025-12-25 00:09:40.522682 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-25 00:10:47.484009 | controller | changed 2025-12-25 00:10:47.493619 | 2025-12-25 00:10:47.493748 | TASK [ensure-podman : Fetch podman version] 2025-12-25 00:10:48.030663 | controller | Client: Podman Engine 2025-12-25 00:10:48.030752 | controller | Version: 4.6.2 2025-12-25 00:10:48.030797 | controller | API Version: 4.6.2 2025-12-25 00:10:48.030837 | controller | Go Version: go1.19.12 2025-12-25 00:10:48.030903 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-25 00:10:48.030950 | controller | OS/Arch: linux/amd64 2025-12-25 00:10:48.530884 | controller | ok: Runtime: 0:00:00.188012 2025-12-25 00:10:48.546657 | 2025-12-25 00:10:48.546845 | TASK [ensure-podman : Print podman version installed] 2025-12-25 00:10:48.589999 | Podman version: Client: Podman Engine 2025-12-25 00:10:48.590365 | Version: 4.6.2 2025-12-25 00:10:48.591203 | API Version: 4.6.2 2025-12-25 00:10:48.591271 | Go Version: go1.19.12 2025-12-25 00:10:48.591315 | Built: Mon Aug 28 19:38:31 2023 2025-12-25 00:10:48.591357 | OS/Arch: linux/amd64 2025-12-25 00:10:48.605198 | 2025-12-25 00:10:48.605339 | TASK [ensure-podman : Validate podman engine] 2025-12-25 00:10:49.147589 | controller | skipping: Conditional result was False 2025-12-25 00:10:49.162714 | 2025-12-25 00:10:49.162870 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-25 00:10:49.190263 | controller | skipping: Conditional result was False 2025-12-25 00:10:49.218901 | 2025-12-25 00:10:49.219140 | TASK [Ensure python3.8 is present] 2025-12-25 00:10:49.238320 | controller | skipping: Conditional result was False 2025-12-25 00:10:49.248453 | 2025-12-25 00:10:49.248562 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-25 00:10:49.271873 | controller | ok 2025-12-25 00:10:49.298394 | 2025-12-25 00:10:49.298496 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-25 00:10:50.679004 | controller | ok: Nothing to do 2025-12-25 00:10:50.689998 | 2025-12-25 00:10:50.690167 | TASK [our-ensure-python : Also install python3-devel] 2025-12-25 00:10:59.623290 | controller | changed 2025-12-25 00:10:59.639939 | 2025-12-25 00:10:59.640103 | TASK [Run ensure-virtualenv role] 2025-12-25 00:10:59.671119 | controller | ok 2025-12-25 00:10:59.696178 | 2025-12-25 00:10:59.696301 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-25 00:10:59.940260 | controller | /usr/bin/virtualenv 2025-12-25 00:11:00.264340 | controller | ok: Runtime: 0:00:00.003122 2025-12-25 00:11:00.277123 | 2025-12-25 00:11:00.277334 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-25 00:11:00.319467 | controller | skipping: Conditional result was False 2025-12-25 00:11:00.320086 | controller | ok: All items complete 2025-12-25 00:11:00.320162 | 2025-12-25 00:11:00.349048 | 2025-12-25 00:11:00.349276 | TASK [Find the full path of the Python interpreter] 2025-12-25 00:11:00.569141 | controller | /usr/bin/python3 2025-12-25 00:11:00.897440 | controller | ok 2025-12-25 00:11:00.905831 | 2025-12-25 00:11:00.905940 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-25 00:11:01.606850 | controller | created virtual environment CPython3.11.0.final.0-64 in 398ms 2025-12-25 00:11:01.624665 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-25 00:11:01.624720 | 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-25 00:11:01.624731 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-25 00:11:01.624748 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-25 00:11:01.941769 | controller | changed 2025-12-25 00:11:01.950174 | 2025-12-25 00:11:01.950280 | TASK [Set selinux package] 2025-12-25 00:11:01.994065 | controller | ok 2025-12-25 00:11:02.001576 | 2025-12-25 00:11:02.001664 | TASK [Set selinux package (Fedora)] 2025-12-25 00:11:02.044563 | controller | ok 2025-12-25 00:11:02.053041 | 2025-12-25 00:11:02.053310 | TASK [Install selinux into virtualenv] 2025-12-25 00:11:27.497813 | controller | Collecting selinux-please-lie-to-me 2025-12-25 00:11:39.757672 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-25 00:11:40.073285 | controller | Collecting setuptools<50.0.0 2025-12-25 00:11:40.079761 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-25 00:11:40.118408 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 23.1 MB/s eta 0:00:00 2025-12-25 00:11:40.199199 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-25 00:11:40.199358 | controller | Attempting uninstall: setuptools 2025-12-25 00:11:40.201731 | controller | Found existing installation: setuptools 62.6.0 2025-12-25 00:11:40.260411 | controller | Uninstalling setuptools-62.6.0: 2025-12-25 00:11:40.268342 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-25 00:11:40.604833 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-25 00:11:52.124357 | controller | 2025-12-25 00:11:52.202264 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-25 00:11:52.202306 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-25 00:11:52.618967 | controller | ok: Runtime: 0:00:49.926647 2025-12-25 00:11:52.627284 | 2025-12-25 00:11:52.627387 | TASK [Install pytest-forked into virtualenv] 2025-12-25 00:12:04.372663 | controller | Collecting pytest-forked 2025-12-25 00:12:28.585880 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-25 00:12:28.630741 | controller | Collecting py 2025-12-25 00:12:28.633930 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-25 00:12:28.659646 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.0 MB/s eta 0:00:00 2025-12-25 00:12:28.760803 | controller | Collecting pytest>=3.10 2025-12-25 00:12:28.765360 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-25 00:12:28.783373 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 24.0 MB/s eta 0:00:00 2025-12-25 00:12:28.819904 | controller | Collecting iniconfig>=1.0.1 2025-12-25 00:12:28.824461 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-25 00:12:28.865703 | controller | Collecting packaging>=22 2025-12-25 00:12:28.868720 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-25 00:12:28.876810 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.4 MB/s eta 0:00:00 2025-12-25 00:12:28.914580 | controller | Collecting pluggy<2,>=1.5 2025-12-25 00:12:28.918309 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-25 00:12:28.968851 | controller | Collecting pygments>=2.7.2 2025-12-25 00:12:28.974748 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-25 00:12:28.992962 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 79.8 MB/s eta 0:00:00 2025-12-25 00:12:29.062078 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-25 00:12:30.121847 | 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-25 00:12:30.130973 | controller | 2025-12-25 00:12:30.205543 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-25 00:12:30.205584 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-25 00:12:30.683091 | controller | ok: Runtime: 0:00:37.370055 2025-12-25 00:12:30.696314 | 2025-12-25 00:12:30.696437 | TASK [Update pip] 2025-12-25 00:12:31.204716 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-25 00:12:40.981483 | controller | Collecting pip 2025-12-25 00:13:05.092967 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-25 00:13:05.148815 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 34.6 MB/s eta 0:00:00 2025-12-25 00:13:05.212026 | controller | Installing collected packages: pip 2025-12-25 00:13:05.212132 | controller | Attempting uninstall: pip 2025-12-25 00:13:05.214282 | controller | Found existing installation: pip 22.2.2 2025-12-25 00:13:05.346145 | controller | Uninstalling pip-22.2.2: 2025-12-25 00:13:05.360894 | controller | Successfully uninstalled pip-22.2.2 2025-12-25 00:13:06.141584 | controller | Successfully installed pip-25.3 2025-12-25 00:13:06.267207 | controller | ok: Runtime: 0:00:35.301176 2025-12-25 00:13:06.275777 | 2025-12-25 00:13:06.275888 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-25 00:13:06.496298 | controller | changed 2025-12-25 00:13:06.505467 | 2025-12-25 00:13:06.505631 | TASK [Install ansible into virtualenv] 2025-12-25 00:13:07.010074 | controller | Processing ./src/github.com/ansible/ansible 2025-12-25 00:13:07.013441 | controller | Installing build dependencies: started 2025-12-25 00:13:32.323585 | controller | Installing build dependencies: finished with status 'done' 2025-12-25 00:13:32.324725 | controller | Getting requirements to build wheel: started 2025-12-25 00:13:33.056808 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-25 00:13:33.058982 | controller | Preparing metadata (pyproject.toml): started 2025-12-25 00:13:33.526481 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-25 00:13:33.531864 | 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-25 00:13:33.535352 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-25 00:13:34.064326 | controller | ERROR 2025-12-25 00:13:34.064599 | controller | { 2025-12-25 00:13:34.064651 | controller | "delta": "0:00:26.884177", 2025-12-25 00:13:34.064690 | controller | "end": "2025-12-25 00:13:33.608583", 2025-12-25 00:13:34.064727 | controller | "msg": "non-zero return code", 2025-12-25 00:13:34.064776 | controller | "rc": 1, 2025-12-25 00:13:34.064812 | controller | "start": "2025-12-25 00:13:06.724406" 2025-12-25 00:13:34.064847 | controller | } failure 2025-12-25 00:13:34.067410 | 2025-12-25 00:13:34.067512 | PLAY RECAP 2025-12-25 00:13:34.067581 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-25 00:13:34.067657 | 2025-12-25 00:13:34.213528 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-25 00:13:34.214515 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-25 00:13:34.820231 | 2025-12-25 00:13:34.820368 | PLAY [all] 2025-12-25 00:13:34.842128 | 2025-12-25 00:13:34.842254 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-25 00:13:35.078967 | controller | changed: non-zero return code 2025-12-25 00:13:35.092596 | 2025-12-25 00:13:35.092778 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-25 00:13:35.118596 | controller | skipping: Conditional result was False 2025-12-25 00:13:35.128603 | 2025-12-25 00:13:35.128734 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-25 00:13:35.164451 | 2025-12-25 00:13:35.164768 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-25 00:13:35.205509 | 2025-12-25 00:13:35.205718 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-25 00:13:35.231429 | controller | skipping: Conditional result was False 2025-12-25 00:13:35.242121 | 2025-12-25 00:13:35.242223 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-25 00:13:35.275622 | 2025-12-25 00:13:35.275800 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-25 00:13:35.301668 | controller | skipping: Conditional result was False 2025-12-25 00:13:35.311357 | 2025-12-25 00:13:35.311483 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-25 00:13:35.337604 | controller | skipping: Conditional result was False 2025-12-25 00:13:35.350914 | 2025-12-25 00:13:35.351091 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-25 00:13:35.377618 | controller | skipping: Conditional result was False 2025-12-25 00:13:35.413873 | 2025-12-25 00:13:35.413990 | PLAY RECAP 2025-12-25 00:13:35.414062 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-25 00:13:35.414087 | 2025-12-25 00:13:35.513710 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-25 00:13:35.514976 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-25 00:13:36.148461 | 2025-12-25 00:13:36.148605 | PLAY [all:!appliance*] 2025-12-25 00:13:36.171084 | 2025-12-25 00:13:36.171194 | TASK [unregister the node] 2025-12-25 00:13:36.701906 | controller | skipping: Conditional result was False 2025-12-25 00:13:36.709284 | 2025-12-25 00:13:36.709385 | TASK [include_role : fetch-output] 2025-12-25 00:13:36.751238 | controller | ok 2025-12-25 00:13:36.771597 | 2025-12-25 00:13:36.771719 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-25 00:13:36.836850 | controller | skipping: Conditional result was False 2025-12-25 00:13:36.844318 | 2025-12-25 00:13:36.844415 | TASK [fetch-output : Set log path for single node] 2025-12-25 00:13:36.893283 | controller | ok 2025-12-25 00:13:36.907127 | 2025-12-25 00:13:36.907272 | LOOP [fetch-output : Ensure local output dirs] 2025-12-25 00:13:37.338252 | controller -> localhost | ok: "/var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/work/logs" 2025-12-25 00:13:37.610815 | controller -> localhost | changed: "/var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/work/artifacts" 2025-12-25 00:13:37.822787 | controller -> localhost | changed: "/var/lib/zuul/builds/045106d8805542c6a7db161f8c311628/work/docs" 2025-12-25 00:13:37.841437 | 2025-12-25 00:13:37.841636 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-25 00:13:38.551678 | controller | changed: 2025-12-25 00:13:38.552182 | controller | .d..t...... ./ 2025-12-25 00:13:38.552257 | controller | cd+++++++++ controller/ 2025-12-25 00:13:38.552333 | controller | changed: All items complete 2025-12-25 00:13:38.552383 | 2025-12-25 00:13:39.077157 | controller | changed: .d..t...... ./ 2025-12-25 00:13:39.647219 | controller | changed: .d..t...... ./ 2025-12-25 00:13:39.666778 | 2025-12-25 00:13:39.666885 | TASK [include_role : fetch-output-openshift] 2025-12-25 00:13:39.681753 | controller | skipping: Conditional result was False 2025-12-25 00:13:39.691664 | 2025-12-25 00:13:39.691787 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-25 00:13:39.717124 | controller | skipping: Conditional result was False 2025-12-25 00:13:39.726693 | controller | skipping: Conditional result was False 2025-12-25 00:13:39.767078 | 2025-12-25 00:13:39.767190 | PLAY [localhost] 2025-12-25 00:13:39.784130 | 2025-12-25 00:13:39.784231 | TASK [Run Zuul manifest role] 2025-12-25 00:13:39.805400 | localhost | ok 2025-12-25 00:13:39.819638 | 2025-12-25 00:13:39.819780 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-25 00:13:40.178619 | localhost | changed 2025-12-25 00:13:40.183091 | 2025-12-25 00:13:40.183161 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-25 00:13:40.221620 | localhost | ok 2025-12-25 00:13:40.229870 | 2025-12-25 00:13:40.229981 | TASK [Set zuul-log-path fact] 2025-12-25 00:13:40.248604 | localhost | ok 2025-12-25 00:13:40.262758 | 2025-12-25 00:13:40.262875 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-25 00:13:40.293657 | localhost | ok 2025-12-25 00:13:40.306484 | 2025-12-25 00:13:40.306609 | LOOP [Run upload-logs-swift role] 2025-12-25 00:13:40.342198 | localhost | Output suppressed because no_log was given 2025-12-25 00:13:40.367195 | 2025-12-25 00:13:40.367310 | TASK [Set zuul-log-path fact] 2025-12-25 00:13:40.391733 | localhost | skipping: Conditional result was False 2025-12-25 00:13:40.396881 | 2025-12-25 00:13:40.396983 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-25 00:13:40.822147 | localhost -> localhost | ok: Runtime: 0:00:00.006028 2025-12-25 00:13:40.855990 | 2025-12-25 00:13:40.856128 | TASK [upload-logs-swift : Upload logs to swift]