2025-12-18 00:23:42.137902 | Job console starting... 2025-12-18 00:23:42.149676 | Updating repositories 2025-12-18 00:23:42.282606 | Preparing job workspace 2025-12-18 00:23:45.847777 | Running Ansible setup... 2025-12-18 00:23:50.800906 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-18 00:23:51.455671 | 2025-12-18 00:23:51.455799 | PLAY [localhost] 2025-12-18 00:23:51.464645 | 2025-12-18 00:23:51.464748 | TASK [Gathering Facts] 2025-12-18 00:23:52.463114 | localhost | ok 2025-12-18 00:23:52.486684 | 2025-12-18 00:23:52.486832 | TASK [Setup log path fact] 2025-12-18 00:23:52.507537 | localhost | ok 2025-12-18 00:23:52.527009 | 2025-12-18 00:23:52.527203 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-18 00:23:52.567864 | localhost | ok 2025-12-18 00:23:52.579979 | 2025-12-18 00:23:52.580153 | TASK [emit-job-header : Print job information] 2025-12-18 00:23:52.622205 | # Job Information 2025-12-18 00:23:52.622392 | Ansible Version: 2.15.12 2025-12-18 00:23:52.622438 | Job: ansible-test-sanity-docker-milestone 2025-12-18 00:23:52.622469 | Pipeline: periodic 2025-12-18 00:23:52.622498 | Executor: ze01.softwarefactory-project.io 2025-12-18 00:23:52.622523 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-18 00:23:52.622555 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/234/ansible/2341f26be5a1431691b527d8fe4218ad/ 2025-12-18 00:23:52.622583 | Event ID: 95f00f3203bf47de8d788a25b598cc45 2025-12-18 00:23:52.628867 | 2025-12-18 00:23:52.628960 | LOOP [emit-job-header : Print node information] 2025-12-18 00:23:52.739571 | localhost | ok: 2025-12-18 00:23:52.739770 | localhost | # Node Information 2025-12-18 00:23:52.739797 | localhost | Inventory Hostname: controller 2025-12-18 00:23:52.739818 | localhost | Hostname: np0005564959 2025-12-18 00:23:52.739838 | localhost | Username: zuul 2025-12-18 00:23:52.739863 | localhost | Distro: Fedora 37 2025-12-18 00:23:52.739882 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-18 00:23:52.739900 | localhost | Region: ca-ymq-1 2025-12-18 00:23:52.739918 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-18 00:23:52.739936 | localhost | Product Name: OpenStack Nova 2025-12-18 00:23:52.739956 | localhost | Interface IP: 162.253.55.227 2025-12-18 00:23:52.755125 | 2025-12-18 00:23:52.755247 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-18 00:23:53.126170 | localhost -> localhost | changed 2025-12-18 00:23:53.133176 | 2025-12-18 00:23:53.133290 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-18 00:23:53.996380 | localhost -> localhost | changed 2025-12-18 00:23:54.029461 | 2025-12-18 00:23:54.029578 | PLAY [all:!appliance*] 2025-12-18 00:23:54.057945 | 2025-12-18 00:23:54.058111 | TASK [include_role : start-zuul-console] 2025-12-18 00:23:54.081610 | controller | ok 2025-12-18 00:23:54.104757 | 2025-12-18 00:23:54.104898 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-18 00:23:54.514663 | controller | ok 2025-12-18 00:23:54.529506 | 2025-12-18 00:23:54.529638 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-18 00:23:55.513502 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-18 00:23:55.520795 | 2025-12-18 00:23:55.520858 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-18 00:23:56.020149 | controller | skipping: Conditional result was False 2025-12-18 00:23:56.026975 | 2025-12-18 00:23:56.027077 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-18 00:23:56.061164 | controller | skipping: Conditional result was False 2025-12-18 00:23:56.068070 | 2025-12-18 00:23:56.068146 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-18 00:23:56.102478 | controller | skipping: Conditional result was False 2025-12-18 00:23:56.115948 | 2025-12-18 00:23:56.116135 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-18 00:23:56.153672 | controller | skipping: Conditional result was False 2025-12-18 00:23:56.167490 | 2025-12-18 00:23:56.167633 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-18 00:23:56.204807 | controller | skipping: Conditional result was False 2025-12-18 00:23:56.218803 | 2025-12-18 00:23:56.219114 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-18 00:23:56.246902 | controller | skipping: Conditional result was False 2025-12-18 00:23:56.275627 | 2025-12-18 00:23:56.275825 | TASK [Disable Fedora Modular] 2025-12-18 00:23:56.680069 | controller | changed 2025-12-18 00:23:56.686562 | 2025-12-18 00:23:56.686645 | TASK [Enable EPEL] 2025-12-18 00:23:56.710931 | controller | skipping: Conditional result was False 2025-12-18 00:23:56.718969 | 2025-12-18 00:23:56.719147 | TASK [Register the RHEL node] 2025-12-18 00:23:57.253760 | 2025-12-18 00:23:57.254280 | TASK [Show the subscription-manager status] 2025-12-18 00:23:57.864645 | controller | skipping: Conditional result was False 2025-12-18 00:23:57.876440 | 2025-12-18 00:23:57.876552 | TASK [Enable EPEL on RHEL] 2025-12-18 00:23:58.412876 | controller | skipping: Conditional result was False 2025-12-18 00:23:58.419678 | 2025-12-18 00:23:58.419820 | TASK [Install git and tox] 2025-12-18 00:25:26.836541 | controller | changed 2025-12-18 00:25:26.842742 | 2025-12-18 00:25:26.842818 | TASK [include_role : prepare-workspace] 2025-12-18 00:25:26.862695 | controller | ok 2025-12-18 00:25:26.885069 | 2025-12-18 00:25:26.885186 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-18 00:25:27.118622 | controller | ok 2025-12-18 00:25:27.128846 | 2025-12-18 00:25:27.128923 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-18 00:25:39.744833 | controller | Output suppressed because no_log was given 2025-12-18 00:25:39.755950 | 2025-12-18 00:25:39.756115 | TASK [include_role : prepare-workspace-openshift] 2025-12-18 00:25:39.781057 | controller | skipping: Conditional result was False 2025-12-18 00:25:39.837589 | 2025-12-18 00:25:39.837664 | PLAY [all:!appliance] 2025-12-18 00:25:39.854065 | 2025-12-18 00:25:39.854153 | TASK [Run add-build-sshkey role (RSA)] 2025-12-18 00:25:39.874395 | controller | ok 2025-12-18 00:25:39.891333 | 2025-12-18 00:25:39.891451 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-18 00:25:40.181075 | controller -> localhost | ok 2025-12-18 00:25:40.189306 | 2025-12-18 00:25:40.189425 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-18 00:25:40.209906 | controller | ok 2025-12-18 00:25:40.223945 | controller | included: /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-18 00:25:40.231171 | 2025-12-18 00:25:40.231259 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-18 00:25:40.715937 | controller -> localhost | Generating public/private rsa key pair. 2025-12-18 00:25:40.716372 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/work/2341f26be5a1431691b527d8fe4218ad_id_rsa. 2025-12-18 00:25:40.716410 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/work/2341f26be5a1431691b527d8fe4218ad_id_rsa.pub. 2025-12-18 00:25:40.716459 | controller -> localhost | The key fingerprint is: 2025-12-18 00:25:40.716493 | controller -> localhost | SHA256:dcdN8UD603Sa5sdPYmZ4np5MlG1WsCOinfn+h7ka9eI zuul-build-sshkey 2025-12-18 00:25:40.716525 | controller -> localhost | The key's randomart image is: 2025-12-18 00:25:40.716557 | controller -> localhost | +---[RSA 2048]----+ 2025-12-18 00:25:40.716580 | controller -> localhost | | .+.o| 2025-12-18 00:25:40.716600 | controller -> localhost | | o *.| 2025-12-18 00:25:40.716618 | controller -> localhost | | o + = *| 2025-12-18 00:25:40.716635 | controller -> localhost | | + = + Oo| 2025-12-18 00:25:40.716652 | controller -> localhost | | S + X =| 2025-12-18 00:25:40.716680 | controller -> localhost | | . * * | 2025-12-18 00:25:40.716708 | controller -> localhost | | + Xo=| 2025-12-18 00:25:40.716729 | controller -> localhost | | . @oBo| 2025-12-18 00:25:40.716747 | controller -> localhost | | o+Eo.| 2025-12-18 00:25:40.716768 | controller -> localhost | +----[SHA256]-----+ 2025-12-18 00:25:40.716817 | controller -> localhost | ok: Runtime: 0:00:00.088464 2025-12-18 00:25:40.724683 | 2025-12-18 00:25:40.724766 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-18 00:25:40.747757 | controller | ok 2025-12-18 00:25:40.759520 | controller | included: /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-18 00:25:40.769006 | 2025-12-18 00:25:40.769160 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-18 00:25:40.805555 | controller | skipping: Conditional result was False 2025-12-18 00:25:40.812707 | 2025-12-18 00:25:40.812802 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-18 00:25:41.266435 | controller | changed 2025-12-18 00:25:41.279605 | 2025-12-18 00:25:41.279800 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-18 00:25:41.514118 | controller | ok 2025-12-18 00:25:41.529182 | 2025-12-18 00:25:41.529338 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-18 00:25:42.169860 | controller | changed 2025-12-18 00:25:42.183706 | 2025-12-18 00:25:42.183865 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-18 00:25:42.889658 | controller | changed 2025-12-18 00:25:42.895653 | 2025-12-18 00:25:42.895735 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-18 00:25:42.920104 | controller | skipping: Conditional result was False 2025-12-18 00:25:42.927255 | 2025-12-18 00:25:42.927381 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-18 00:25:43.331616 | controller -> localhost | changed 2025-12-18 00:25:43.350465 | 2025-12-18 00:25:43.350605 | TASK [add-build-sshkey : Add back temp key] 2025-12-18 00:25:43.640526 | controller -> localhost | Identity added: /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/work/2341f26be5a1431691b527d8fe4218ad_id_rsa (zuul-build-sshkey) 2025-12-18 00:25:43.640759 | controller -> localhost | ok: Runtime: 0:00:00.013170 2025-12-18 00:25:43.647662 | 2025-12-18 00:25:43.647742 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-18 00:25:43.991680 | controller | ok 2025-12-18 00:25:44.005361 | 2025-12-18 00:25:44.005519 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-18 00:25:44.032398 | controller | skipping: Conditional result was False 2025-12-18 00:25:44.061837 | 2025-12-18 00:25:44.062078 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-18 00:25:44.096121 | controller | ok 2025-12-18 00:25:44.123590 | 2025-12-18 00:25:44.123741 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-18 00:25:44.374666 | controller -> localhost | ok 2025-12-18 00:25:44.392741 | 2025-12-18 00:25:44.392911 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-18 00:25:44.417587 | controller | ok 2025-12-18 00:25:44.433153 | controller | included: /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-18 00:25:44.441797 | 2025-12-18 00:25:44.441903 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-18 00:25:44.754930 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-18 00:25:44.755310 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/work/2341f26be5a1431691b527d8fe4218ad_id_ecdsa. 2025-12-18 00:25:44.755373 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/work/2341f26be5a1431691b527d8fe4218ad_id_ecdsa.pub. 2025-12-18 00:25:44.755437 | controller -> localhost | The key fingerprint is: 2025-12-18 00:25:44.755482 | controller -> localhost | SHA256:zCsfjXNHn3EpwnkZyBk1qsSjrfPa9TYfnMwz7hdMG2M zuul-build-sshkey 2025-12-18 00:25:44.755524 | controller -> localhost | The key's randomart image is: 2025-12-18 00:25:44.755692 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-18 00:25:44.755794 | controller -> localhost | | ..o | 2025-12-18 00:25:44.755893 | controller -> localhost | | . . = . | 2025-12-18 00:25:44.756212 | controller -> localhost | | + = . | 2025-12-18 00:25:44.756399 | controller -> localhost | | o+ + . oE.| 2025-12-18 00:25:44.756521 | controller -> localhost | | .So +.+=.=| 2025-12-18 00:25:44.756637 | controller -> localhost | | .+ .o.=B.| 2025-12-18 00:25:44.756838 | controller -> localhost | | .o= o.. oO.| 2025-12-18 00:25:44.757004 | controller -> localhost | | o++...o. =| 2025-12-18 00:25:44.757283 | controller -> localhost | | .oo ..++.| 2025-12-18 00:25:44.758110 | controller -> localhost | +----[SHA256]-----+ 2025-12-18 00:25:44.758816 | controller -> localhost | ok: Runtime: 0:00:00.008323 2025-12-18 00:25:44.776493 | 2025-12-18 00:25:44.776667 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-18 00:25:44.807912 | controller | ok 2025-12-18 00:25:44.829295 | controller | included: /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-18 00:25:44.844706 | 2025-12-18 00:25:44.844855 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-18 00:25:44.860491 | controller | skipping: Conditional result was False 2025-12-18 00:25:44.871368 | 2025-12-18 00:25:44.871524 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-18 00:25:45.158832 | controller | changed 2025-12-18 00:25:45.176372 | 2025-12-18 00:25:45.176584 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-18 00:25:45.421274 | controller | ok 2025-12-18 00:25:45.437870 | 2025-12-18 00:25:45.438260 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-18 00:25:46.109042 | controller | changed 2025-12-18 00:25:46.123694 | 2025-12-18 00:25:46.123897 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-18 00:25:46.784104 | controller | changed 2025-12-18 00:25:46.798488 | 2025-12-18 00:25:46.798645 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-18 00:25:46.825213 | controller | skipping: Conditional result was False 2025-12-18 00:25:46.835805 | 2025-12-18 00:25:46.835931 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-18 00:25:47.087692 | controller -> localhost | changed 2025-12-18 00:25:47.107762 | 2025-12-18 00:25:47.107900 | TASK [add-build-sshkey : Add back temp key] 2025-12-18 00:25:47.421283 | controller -> localhost | Identity added: /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/work/2341f26be5a1431691b527d8fe4218ad_id_ecdsa (zuul-build-sshkey) 2025-12-18 00:25:47.421673 | controller -> localhost | ok: Runtime: 0:00:00.006878 2025-12-18 00:25:47.435996 | 2025-12-18 00:25:47.436175 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-18 00:25:47.699629 | controller | ok 2025-12-18 00:25:47.709010 | 2025-12-18 00:25:47.709123 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-18 00:25:47.743493 | controller | skipping: Conditional result was False 2025-12-18 00:25:47.755575 | 2025-12-18 00:25:47.755711 | TASK [include_role : remove-zuul-sshkey] 2025-12-18 00:25:47.770969 | controller | skipping: Conditional result was False 2025-12-18 00:25:47.783495 | 2025-12-18 00:25:47.783641 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-18 00:25:48.031471 | controller | ok: "logs" 2025-12-18 00:25:48.031720 | controller | ok: All items complete 2025-12-18 00:25:48.031749 | 2025-12-18 00:25:48.250862 | controller | ok: "artifacts" 2025-12-18 00:25:48.469113 | controller | ok: "docs" 2025-12-18 00:25:48.494225 | 2025-12-18 00:25:48.496068 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-18 00:25:48.782517 | controller | changed: "logs" 2025-12-18 00:25:48.984522 | controller | changed: "artifacts" 2025-12-18 00:25:49.186601 | controller | changed: "docs" 2025-12-18 00:25:49.250287 | 2025-12-18 00:25:49.250413 | PLAY RECAP 2025-12-18 00:25:49.250471 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-18 00:25:49.250506 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-18 00:25:49.250532 | 2025-12-18 00:25:49.383381 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-18 00:25:49.384596 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-18 00:25:50.012518 | 2025-12-18 00:25:50.012646 | PLAY [all] 2025-12-18 00:25:50.035307 | 2025-12-18 00:25:50.035434 | TASK [Install binary dependencies] 2025-12-18 00:25:50.118504 | controller | ok 2025-12-18 00:25:50.139971 | 2025-12-18 00:25:50.140124 | TASK [bindep : Include find tasks] 2025-12-18 00:25:50.169724 | controller | ok 2025-12-18 00:25:50.177584 | controller | included: /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-18 00:25:50.183820 | 2025-12-18 00:25:50.183885 | TASK [bindep : Look for bindep.txt] 2025-12-18 00:25:50.521548 | controller | ok 2025-12-18 00:25:50.528077 | 2025-12-18 00:25:50.528192 | TASK [bindep : Define bindep_file fact] 2025-12-18 00:25:50.552786 | controller | skipping: Conditional result was False 2025-12-18 00:25:50.559968 | 2025-12-18 00:25:50.560104 | TASK [bindep : Look for other-requirements.txt] 2025-12-18 00:25:50.763622 | controller | ok 2025-12-18 00:25:50.769464 | 2025-12-18 00:25:50.769537 | TASK [bindep : Define bindep_file fact] 2025-12-18 00:25:50.793638 | controller | skipping: Conditional result was False 2025-12-18 00:25:50.799814 | 2025-12-18 00:25:50.799890 | TASK [bindep : Look for bindep fallback file] 2025-12-18 00:25:50.825133 | controller | skipping: Conditional result was False 2025-12-18 00:25:50.836406 | 2025-12-18 00:25:50.836574 | TASK [bindep : Define bindep_file fact] 2025-12-18 00:25:50.864166 | controller | skipping: Conditional result was False 2025-12-18 00:25:50.873851 | 2025-12-18 00:25:50.873976 | TASK [bindep : Include bindep tasks] 2025-12-18 00:25:50.899762 | controller | skipping: Conditional result was False 2025-12-18 00:25:50.909386 | 2025-12-18 00:25:50.909601 | TASK [bindep : Include install tasks] 2025-12-18 00:25:50.935007 | controller | skipping: Conditional result was False 2025-12-18 00:25:50.944223 | 2025-12-18 00:25:50.944357 | LOOP [bindep : Include package tasks] 2025-12-18 00:25:51.006857 | 2025-12-18 00:25:51.007094 | TASK [Run test-setup role] 2025-12-18 00:25:51.032340 | controller | ok 2025-12-18 00:25:51.057989 | 2025-12-18 00:25:51.058178 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-18 00:25:51.307107 | controller | ok 2025-12-18 00:25:51.315231 | 2025-12-18 00:25:51.315342 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-18 00:25:51.849226 | controller | skipping: Conditional result was False 2025-12-18 00:25:51.908398 | 2025-12-18 00:25:51.908518 | PLAY RECAP 2025-12-18 00:25:51.908572 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-18 00:25:51.908604 | 2025-12-18 00:25:52.023615 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-18 00:25:52.024486 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-18 00:25:52.620927 | 2025-12-18 00:25:52.621099 | PLAY [controller] 2025-12-18 00:25:52.648315 | 2025-12-18 00:25:52.648499 | TASK [Create the /root directory] 2025-12-18 00:25:53.037206 | controller | ok 2025-12-18 00:25:53.052863 | 2025-12-18 00:25:53.053085 | TASK [Install glibc-langpack-en] 2025-12-18 00:25:57.082081 | controller | ok: Nothing to do 2025-12-18 00:25:57.088417 | 2025-12-18 00:25:57.088518 | TASK [Ensure controller directory exists] 2025-12-18 00:25:57.322970 | controller | changed 2025-12-18 00:25:57.329303 | 2025-12-18 00:25:57.329381 | TASK [Install container runtime] 2025-12-18 00:25:57.380192 | controller | ok 2025-12-18 00:25:57.422510 | 2025-12-18 00:25:57.422640 | LOOP [ensure-podman : Find distribution installation] 2025-12-18 00:25:57.453354 | controller | ok: "/var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-18 00:25:57.465501 | controller | included: /var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-18 00:25:57.472307 | 2025-12-18 00:25:57.472379 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-18 00:27:19.022119 | controller | changed 2025-12-18 00:27:19.040866 | 2025-12-18 00:27:19.041008 | TASK [ensure-podman : Fetch podman version] 2025-12-18 00:27:19.608778 | controller | Client: Podman Engine 2025-12-18 00:27:19.643123 | controller | Version: 4.6.2 2025-12-18 00:27:19.643174 | controller | API Version: 4.6.2 2025-12-18 00:27:19.643188 | controller | Go Version: go1.19.12 2025-12-18 00:27:19.643226 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-18 00:27:19.643239 | controller | OS/Arch: linux/amd64 2025-12-18 00:27:20.105641 | controller | ok: Runtime: 0:00:00.194922 2025-12-18 00:27:20.113690 | 2025-12-18 00:27:20.113797 | TASK [ensure-podman : Print podman version installed] 2025-12-18 00:27:20.153589 | Podman version: Client: Podman Engine 2025-12-18 00:27:20.153804 | Version: 4.6.2 2025-12-18 00:27:20.153846 | API Version: 4.6.2 2025-12-18 00:27:20.153876 | Go Version: go1.19.12 2025-12-18 00:27:20.153903 | Built: Mon Aug 28 19:38:31 2023 2025-12-18 00:27:20.153932 | OS/Arch: linux/amd64 2025-12-18 00:27:20.164179 | 2025-12-18 00:27:20.164309 | TASK [ensure-podman : Validate podman engine] 2025-12-18 00:27:20.707432 | controller | skipping: Conditional result was False 2025-12-18 00:27:20.724037 | 2025-12-18 00:27:20.724175 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-18 00:27:20.748914 | controller | skipping: Conditional result was False 2025-12-18 00:27:20.766812 | 2025-12-18 00:27:20.766942 | TASK [Ensure python3.8 is present] 2025-12-18 00:27:20.781488 | controller | skipping: Conditional result was False 2025-12-18 00:27:20.793386 | 2025-12-18 00:27:20.793517 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-18 00:27:20.817661 | controller | ok 2025-12-18 00:27:20.844380 | 2025-12-18 00:27:20.844492 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-18 00:27:22.445199 | controller | ok: Nothing to do 2025-12-18 00:27:22.453485 | 2025-12-18 00:27:22.453891 | TASK [our-ensure-python : Also install python3-devel] 2025-12-18 00:27:32.624249 | controller | changed 2025-12-18 00:27:32.637340 | 2025-12-18 00:27:32.637463 | TASK [Run ensure-virtualenv role] 2025-12-18 00:27:32.668073 | controller | ok 2025-12-18 00:27:32.694152 | 2025-12-18 00:27:32.694318 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-18 00:27:32.916160 | controller | /usr/bin/virtualenv 2025-12-18 00:27:33.227744 | controller | ok: Runtime: 0:00:00.004949 2025-12-18 00:27:33.278295 | 2025-12-18 00:27:33.278408 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-18 00:27:33.295889 | controller | skipping: Conditional result was False 2025-12-18 00:27:33.296181 | controller | ok: All items complete 2025-12-18 00:27:33.296227 | 2025-12-18 00:27:33.313500 | 2025-12-18 00:27:33.313606 | TASK [Find the full path of the Python interpreter] 2025-12-18 00:27:33.535415 | controller | /usr/bin/python3 2025-12-18 00:27:33.846090 | controller | ok 2025-12-18 00:27:33.852054 | 2025-12-18 00:27:33.852121 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-18 00:27:34.588614 | controller | created virtual environment CPython3.11.0.final.0-64 in 407ms 2025-12-18 00:27:34.603677 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-18 00:27:34.603716 | 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-18 00:27:34.603726 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-18 00:27:34.603739 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-18 00:27:34.890430 | controller | changed 2025-12-18 00:27:34.897252 | 2025-12-18 00:27:34.897360 | TASK [Set selinux package] 2025-12-18 00:27:34.918809 | controller | ok 2025-12-18 00:27:34.924790 | 2025-12-18 00:27:34.924867 | TASK [Set selinux package (Fedora)] 2025-12-18 00:27:34.955412 | controller | ok 2025-12-18 00:27:34.961630 | 2025-12-18 00:27:34.961982 | TASK [Install selinux into virtualenv] 2025-12-18 00:28:00.452509 | controller | Collecting selinux-please-lie-to-me 2025-12-18 00:29:00.552316 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-18 00:29:00.859600 | controller | Collecting setuptools<50.0.0 2025-12-18 00:29:00.878634 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-18 00:29:00.907688 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 32.0 MB/s eta 0:00:00 2025-12-18 00:29:00.984434 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-18 00:29:00.984645 | controller | Attempting uninstall: setuptools 2025-12-18 00:29:00.987181 | controller | Found existing installation: setuptools 62.6.0 2025-12-18 00:29:01.046127 | controller | Uninstalling setuptools-62.6.0: 2025-12-18 00:29:01.054571 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-18 00:29:01.395105 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-18 00:29:17.685618 | controller | 2025-12-18 00:29:17.765683 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-18 00:29:17.765725 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-18 00:29:18.049224 | controller | ok: Runtime: 0:01:42.586183 2025-12-18 00:29:18.058255 | 2025-12-18 00:29:18.058395 | TASK [Install pytest-forked into virtualenv] 2025-12-18 00:29:41.873466 | controller | Collecting pytest-forked 2025-12-18 00:30:06.178937 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-18 00:30:06.223942 | controller | Collecting py 2025-12-18 00:30:06.230597 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-18 00:30:06.253401 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.6 MB/s eta 0:00:00 2025-12-18 00:30:06.364027 | controller | Collecting pytest>=3.10 2025-12-18 00:30:06.369184 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-18 00:30:06.383854 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 31.8 MB/s eta 0:00:00 2025-12-18 00:30:06.422564 | controller | Collecting iniconfig>=1.0.1 2025-12-18 00:30:06.426240 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-18 00:30:06.476113 | controller | Collecting packaging>=22 2025-12-18 00:30:06.479692 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-18 00:30:06.488233 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.9 MB/s eta 0:00:00 2025-12-18 00:30:06.525572 | controller | Collecting pluggy<2,>=1.5 2025-12-18 00:30:06.529110 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-18 00:30:06.575523 | controller | Collecting pygments>=2.7.2 2025-12-18 00:30:06.578547 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-18 00:30:06.609721 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 48.7 MB/s eta 0:00:00 2025-12-18 00:30:06.679717 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-18 00:30:07.713429 | 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-18 00:30:07.722195 | controller | 2025-12-18 00:30:07.789888 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-18 00:30:07.789932 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-18 00:30:08.125036 | controller | ok: Runtime: 0:00:49.501399 2025-12-18 00:30:08.132202 | 2025-12-18 00:30:08.132317 | TASK [Update pip] 2025-12-18 00:30:08.637484 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-18 00:30:21.059137 | controller | Collecting pip 2025-12-18 00:30:33.249741 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-18 00:30:33.310166 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 32.3 MB/s eta 0:00:00 2025-12-18 00:30:33.375406 | controller | Installing collected packages: pip 2025-12-18 00:30:33.375550 | controller | Attempting uninstall: pip 2025-12-18 00:30:33.377697 | controller | Found existing installation: pip 22.2.2 2025-12-18 00:30:33.523510 | controller | Uninstalling pip-22.2.2: 2025-12-18 00:30:33.539448 | controller | Successfully uninstalled pip-22.2.2 2025-12-18 00:30:34.522628 | controller | Successfully installed pip-25.3 2025-12-18 00:30:34.688486 | controller | ok: Runtime: 0:00:26.282147 2025-12-18 00:30:34.694685 | 2025-12-18 00:30:34.694794 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-18 00:30:34.926256 | controller | changed 2025-12-18 00:30:34.939009 | 2025-12-18 00:30:34.939186 | TASK [Install ansible into virtualenv] 2025-12-18 00:30:35.487760 | controller | Processing ./src/github.com/ansible/ansible 2025-12-18 00:30:35.491046 | controller | Installing build dependencies: started 2025-12-18 00:30:55.106262 | controller | Installing build dependencies: finished with status 'done' 2025-12-18 00:30:55.106834 | controller | Getting requirements to build wheel: started 2025-12-18 00:30:55.850893 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-18 00:30:55.851790 | controller | Preparing metadata (pyproject.toml): started 2025-12-18 00:30:56.319024 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-18 00:30:56.324492 | 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-18 00:30:56.329536 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-18 00:30:56.530954 | controller | ERROR 2025-12-18 00:30:56.531265 | controller | { 2025-12-18 00:30:56.531617 | controller | "delta": "0:00:21.188441", 2025-12-18 00:30:56.531754 | controller | "end": "2025-12-18 00:30:56.390814", 2025-12-18 00:30:56.531796 | controller | "msg": "non-zero return code", 2025-12-18 00:30:56.531838 | controller | "rc": 1, 2025-12-18 00:30:56.531864 | controller | "start": "2025-12-18 00:30:35.202373" 2025-12-18 00:30:56.531971 | controller | } failure 2025-12-18 00:30:56.536509 | 2025-12-18 00:30:56.536701 | PLAY RECAP 2025-12-18 00:30:56.536880 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-18 00:30:56.536923 | 2025-12-18 00:30:56.691470 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-18 00:30:56.692956 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-18 00:30:57.335274 | 2025-12-18 00:30:57.335391 | PLAY [all] 2025-12-18 00:30:57.358101 | 2025-12-18 00:30:57.358209 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-18 00:30:57.621429 | controller | changed: non-zero return code 2025-12-18 00:30:57.635238 | 2025-12-18 00:30:57.635403 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-18 00:30:57.662198 | controller | skipping: Conditional result was False 2025-12-18 00:30:57.671155 | 2025-12-18 00:30:57.671267 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-18 00:30:57.707401 | 2025-12-18 00:30:57.707594 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-18 00:30:57.743989 | 2025-12-18 00:30:57.744250 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-18 00:30:57.761173 | controller | skipping: Conditional result was False 2025-12-18 00:30:57.775168 | 2025-12-18 00:30:57.775346 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-18 00:30:57.813245 | 2025-12-18 00:30:57.813444 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-18 00:30:57.827989 | controller | skipping: Conditional result was False 2025-12-18 00:30:57.836176 | 2025-12-18 00:30:57.836316 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-18 00:30:57.851414 | controller | skipping: Conditional result was False 2025-12-18 00:30:57.858619 | 2025-12-18 00:30:57.858751 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-18 00:30:57.873271 | controller | skipping: Conditional result was False 2025-12-18 00:30:57.905271 | 2025-12-18 00:30:57.905384 | PLAY RECAP 2025-12-18 00:30:57.905422 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-18 00:30:57.905443 | 2025-12-18 00:30:58.032206 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-18 00:30:58.033128 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-18 00:30:58.648248 | 2025-12-18 00:30:58.648382 | PLAY [all:!appliance*] 2025-12-18 00:30:58.672792 | 2025-12-18 00:30:58.672936 | TASK [unregister the node] 2025-12-18 00:30:59.205515 | controller | skipping: Conditional result was False 2025-12-18 00:30:59.216646 | 2025-12-18 00:30:59.216937 | TASK [include_role : fetch-output] 2025-12-18 00:30:59.252383 | controller | ok 2025-12-18 00:30:59.278338 | 2025-12-18 00:30:59.278469 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-18 00:30:59.324760 | controller | skipping: Conditional result was False 2025-12-18 00:30:59.331221 | 2025-12-18 00:30:59.331294 | TASK [fetch-output : Set log path for single node] 2025-12-18 00:30:59.361062 | controller | ok 2025-12-18 00:30:59.366890 | 2025-12-18 00:30:59.366965 | LOOP [fetch-output : Ensure local output dirs] 2025-12-18 00:30:59.805098 | controller -> localhost | ok: "/var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/work/logs" 2025-12-18 00:31:00.021351 | controller -> localhost | changed: "/var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/work/artifacts" 2025-12-18 00:31:00.268100 | controller -> localhost | changed: "/var/lib/zuul/builds/2341f26be5a1431691b527d8fe4218ad/work/docs" 2025-12-18 00:31:00.292585 | 2025-12-18 00:31:00.292785 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-18 00:31:00.987563 | controller | changed: 2025-12-18 00:31:00.987966 | controller | .d..t...... ./ 2025-12-18 00:31:00.988062 | controller | cd+++++++++ controller/ 2025-12-18 00:31:00.988136 | controller | changed: All items complete 2025-12-18 00:31:00.988179 | 2025-12-18 00:31:01.493009 | controller | changed: .d..t...... ./ 2025-12-18 00:31:01.969308 | controller | changed: .d..t...... ./ 2025-12-18 00:31:01.989857 | 2025-12-18 00:31:01.989989 | TASK [include_role : fetch-output-openshift] 2025-12-18 00:31:02.005484 | controller | skipping: Conditional result was False 2025-12-18 00:31:02.019214 | 2025-12-18 00:31:02.019375 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-18 00:31:02.065800 | controller | skipping: Conditional result was False 2025-12-18 00:31:02.079768 | controller | skipping: Conditional result was False 2025-12-18 00:31:02.128547 | 2025-12-18 00:31:02.128697 | PLAY [localhost] 2025-12-18 00:31:02.149115 | 2025-12-18 00:31:02.149241 | TASK [Run Zuul manifest role] 2025-12-18 00:31:02.168892 | localhost | ok 2025-12-18 00:31:02.184680 | 2025-12-18 00:31:02.184803 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-18 00:31:02.590249 | localhost | changed 2025-12-18 00:31:02.604550 | 2025-12-18 00:31:02.604761 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-18 00:31:02.637861 | localhost | ok 2025-12-18 00:31:02.651171 | 2025-12-18 00:31:02.651283 | TASK [Set zuul-log-path fact] 2025-12-18 00:31:02.676730 | localhost | ok 2025-12-18 00:31:02.697873 | 2025-12-18 00:31:02.698012 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-18 00:31:02.741646 | localhost | ok 2025-12-18 00:31:02.753921 | 2025-12-18 00:31:02.754047 | LOOP [Run upload-logs-swift role] 2025-12-18 00:31:02.789931 | localhost | Output suppressed because no_log was given 2025-12-18 00:31:02.816603 | 2025-12-18 00:31:02.816722 | TASK [Set zuul-log-path fact] 2025-12-18 00:31:02.841253 | localhost | skipping: Conditional result was False 2025-12-18 00:31:02.847089 | 2025-12-18 00:31:02.847179 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-18 00:31:03.300504 | localhost -> localhost | ok: Runtime: 0:00:00.004858 2025-12-18 00:31:03.307366 | 2025-12-18 00:31:03.307446 | TASK [upload-logs-swift : Upload logs to swift]