2025-11-01 00:18:46.727855 | Job console starting... 2025-11-01 00:18:46.739690 | Updating repositories 2025-11-01 00:18:46.892290 | Preparing job workspace 2025-11-01 00:18:50.649396 | Running Ansible setup... 2025-11-01 00:18:56.849177 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-01 00:18:57.471694 | 2025-11-01 00:18:57.471826 | PLAY [localhost] 2025-11-01 00:18:57.480141 | 2025-11-01 00:18:57.480237 | TASK [Gathering Facts] 2025-11-01 00:18:58.389617 | localhost | ok 2025-11-01 00:18:58.403149 | 2025-11-01 00:18:58.403226 | TASK [Setup log path fact] 2025-11-01 00:18:58.430571 | localhost | ok 2025-11-01 00:18:58.442890 | 2025-11-01 00:18:58.442955 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-01 00:18:58.470419 | localhost | ok 2025-11-01 00:18:58.478236 | 2025-11-01 00:18:58.478309 | TASK [emit-job-header : Print job information] 2025-11-01 00:18:58.526102 | # Job Information 2025-11-01 00:18:58.526265 | Ansible Version: 2.15.12 2025-11-01 00:18:58.526298 | Job: ansible-test-sanity-docker-milestone 2025-11-01 00:18:58.526321 | Pipeline: periodic 2025-11-01 00:18:58.526342 | Executor: ze01.softwarefactory-project.io 2025-11-01 00:18:58.526360 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-01 00:18:58.526380 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/074/ansible/0742b9c98fe84dbab2943cde3fcda4b1/ 2025-11-01 00:18:58.526399 | Event ID: a664f74adefa4145bbf2cab5da247121 2025-11-01 00:18:58.530176 | 2025-11-01 00:18:58.530237 | LOOP [emit-job-header : Print node information] 2025-11-01 00:18:58.642093 | localhost | ok: 2025-11-01 00:18:58.642388 | localhost | # Node Information 2025-11-01 00:18:58.642454 | localhost | Inventory Hostname: controller 2025-11-01 00:18:58.642499 | localhost | Hostname: ip-172-16-0-9 2025-11-01 00:18:58.642543 | localhost | Username: zuul-worker 2025-11-01 00:18:58.642590 | localhost | Distro: Fedora 37 2025-11-01 00:18:58.642633 | localhost | Provider: ansible-us-east-2 2025-11-01 00:18:58.642672 | localhost | Region: us-east-2 2025-11-01 00:18:58.642710 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-01 00:18:58.642748 | localhost | Product Name: t3.small 2025-11-01 00:18:58.642788 | localhost | Interface IP: 18.118.55.32 2025-11-01 00:18:58.664663 | 2025-11-01 00:18:58.665121 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-01 00:18:59.095952 | localhost -> localhost | changed 2025-11-01 00:18:59.101764 | 2025-11-01 00:18:59.101833 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-01 00:19:00.008590 | localhost -> localhost | changed 2025-11-01 00:19:00.028112 | 2025-11-01 00:19:00.028193 | PLAY [all:!appliance*] 2025-11-01 00:19:00.043056 | 2025-11-01 00:19:00.043121 | TASK [include_role : start-zuul-console] 2025-11-01 00:19:00.061409 | controller | ok 2025-11-01 00:19:00.074111 | 2025-11-01 00:19:00.074174 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-01 00:19:00.746230 | controller | ok 2025-11-01 00:19:00.757421 | 2025-11-01 00:19:00.757502 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-01 00:19:02.611374 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-01 00:19:02.620582 | 2025-11-01 00:19:02.620671 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-01 00:19:02.765571 | controller | skipping: Conditional result was False 2025-11-01 00:19:02.773970 | 2025-11-01 00:19:02.774086 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-01 00:19:02.799207 | controller | skipping: Conditional result was False 2025-11-01 00:19:02.807488 | 2025-11-01 00:19:02.807577 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-01 00:19:02.832287 | controller | skipping: Conditional result was False 2025-11-01 00:19:02.840395 | 2025-11-01 00:19:02.840490 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-01 00:19:02.865062 | controller | skipping: Conditional result was False 2025-11-01 00:19:02.874159 | 2025-11-01 00:19:02.874295 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-01 00:19:02.900836 | controller | skipping: Conditional result was False 2025-11-01 00:19:02.914898 | 2025-11-01 00:19:02.915076 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-01 00:19:02.941884 | controller | skipping: Conditional result was False 2025-11-01 00:19:02.968650 | 2025-11-01 00:19:02.968847 | TASK [Disable Fedora Modular] 2025-11-01 00:19:03.775626 | controller | changed 2025-11-01 00:19:03.781441 | 2025-11-01 00:19:03.781514 | TASK [Enable EPEL] 2025-11-01 00:19:03.806414 | controller | skipping: Conditional result was False 2025-11-01 00:19:03.816693 | 2025-11-01 00:19:03.816830 | TASK [Register the RHEL node] 2025-11-01 00:19:03.997815 | 2025-11-01 00:19:03.998159 | TASK [Show the subscription-manager status] 2025-11-01 00:19:04.175327 | controller | skipping: Conditional result was False 2025-11-01 00:19:04.181711 | 2025-11-01 00:19:04.181803 | TASK [Enable EPEL on RHEL] 2025-11-01 00:19:04.325813 | controller | skipping: Conditional result was False 2025-11-01 00:19:04.331874 | 2025-11-01 00:19:04.331943 | TASK [Install git and tox] 2025-11-01 00:20:37.929950 | controller | changed 2025-11-01 00:20:37.946079 | 2025-11-01 00:20:37.946622 | TASK [include_role : prepare-workspace] 2025-11-01 00:20:37.988751 | controller | ok 2025-11-01 00:20:38.028224 | 2025-11-01 00:20:38.028344 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-01 00:20:38.588462 | controller | ok 2025-11-01 00:20:38.605268 | 2025-11-01 00:20:38.605429 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-01 00:20:51.136323 | controller | Output suppressed because no_log was given 2025-11-01 00:20:51.151899 | 2025-11-01 00:20:51.152008 | TASK [include_role : prepare-workspace-openshift] 2025-11-01 00:20:51.169577 | controller | skipping: Conditional result was False 2025-11-01 00:20:51.196924 | 2025-11-01 00:20:51.197045 | PLAY [all:!appliance] 2025-11-01 00:20:51.217911 | 2025-11-01 00:20:51.218080 | TASK [Run add-build-sshkey role (RSA)] 2025-11-01 00:20:51.238168 | controller | ok 2025-11-01 00:20:51.252663 | 2025-11-01 00:20:51.252761 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-01 00:20:51.514845 | controller -> localhost | ok 2025-11-01 00:20:51.532894 | 2025-11-01 00:20:51.533106 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-01 00:20:51.636011 | controller | ok 2025-11-01 00:20:51.656114 | controller | included: /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-01 00:20:51.662664 | 2025-11-01 00:20:51.662732 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-01 00:20:52.150976 | controller -> localhost | Generating public/private rsa key pair. 2025-11-01 00:20:52.151181 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/work/0742b9c98fe84dbab2943cde3fcda4b1_id_rsa. 2025-11-01 00:20:52.151210 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/work/0742b9c98fe84dbab2943cde3fcda4b1_id_rsa.pub. 2025-11-01 00:20:52.151231 | controller -> localhost | The key fingerprint is: 2025-11-01 00:20:52.151250 | controller -> localhost | SHA256:aLk8JYqyarmvKK+JroaJQDo7dTyJUn2rkdxwHbMsaFs zuul-build-sshkey 2025-11-01 00:20:52.151270 | controller -> localhost | The key's randomart image is: 2025-11-01 00:20:52.151288 | controller -> localhost | +---[RSA 2048]----+ 2025-11-01 00:20:52.151306 | controller -> localhost | | | 2025-11-01 00:20:52.151325 | controller -> localhost | | o | 2025-11-01 00:20:52.151343 | controller -> localhost | | . . o + | 2025-11-01 00:20:52.151360 | controller -> localhost | | .. = Eo+ | 2025-11-01 00:20:52.151378 | controller -> localhost | |o. = X=oS | 2025-11-01 00:20:52.151406 | controller -> localhost | |= o.X+o+ | 2025-11-01 00:20:52.151429 | controller -> localhost | |=*o..++ | 2025-11-01 00:20:52.151448 | controller -> localhost | |XB . . | 2025-11-01 00:20:52.151466 | controller -> localhost | |/B=. | 2025-11-01 00:20:52.151487 | controller -> localhost | +----[SHA256]-----+ 2025-11-01 00:20:52.151535 | controller -> localhost | ok: Runtime: 0:00:00.079755 2025-11-01 00:20:52.158757 | 2025-11-01 00:20:52.158843 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-01 00:20:52.179753 | controller | ok 2025-11-01 00:20:52.192360 | controller | included: /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-01 00:20:52.203052 | 2025-11-01 00:20:52.203188 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-01 00:20:52.217758 | controller | skipping: Conditional result was False 2025-11-01 00:20:52.226206 | 2025-11-01 00:20:52.226327 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-01 00:20:52.821399 | controller | changed 2025-11-01 00:20:52.830471 | 2025-11-01 00:20:52.830598 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-01 00:20:53.159898 | controller | ok 2025-11-01 00:20:53.166132 | 2025-11-01 00:20:53.166247 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-01 00:20:54.482948 | controller | changed 2025-11-01 00:20:54.495091 | 2025-11-01 00:20:54.495223 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-01 00:20:55.833686 | controller | changed 2025-11-01 00:20:55.846849 | 2025-11-01 00:20:55.847075 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-01 00:20:55.885374 | controller | skipping: Conditional result was False 2025-11-01 00:20:55.899295 | 2025-11-01 00:20:55.899505 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-01 00:20:56.277841 | controller -> localhost | changed 2025-11-01 00:20:56.302296 | 2025-11-01 00:20:56.302451 | TASK [add-build-sshkey : Add back temp key] 2025-11-01 00:20:56.585812 | controller -> localhost | Identity added: /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/work/0742b9c98fe84dbab2943cde3fcda4b1_id_rsa (zuul-build-sshkey) 2025-11-01 00:20:56.586046 | controller -> localhost | ok: Runtime: 0:00:00.012026 2025-11-01 00:20:56.592323 | 2025-11-01 00:20:56.592394 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-01 00:20:57.030648 | controller | ok 2025-11-01 00:20:57.043946 | 2025-11-01 00:20:57.044102 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-01 00:20:57.068611 | controller | skipping: Conditional result was False 2025-11-01 00:20:57.080885 | 2025-11-01 00:20:57.080977 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-01 00:20:57.101310 | controller | ok 2025-11-01 00:20:57.119007 | 2025-11-01 00:20:57.119131 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-01 00:20:57.377106 | controller -> localhost | ok 2025-11-01 00:20:57.385675 | 2025-11-01 00:20:57.385758 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-01 00:20:57.406334 | controller | ok 2025-11-01 00:20:57.418041 | controller | included: /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-01 00:20:57.426594 | 2025-11-01 00:20:57.426685 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-01 00:20:57.766786 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-01 00:20:57.766953 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/work/0742b9c98fe84dbab2943cde3fcda4b1_id_ecdsa. 2025-11-01 00:20:57.766980 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/work/0742b9c98fe84dbab2943cde3fcda4b1_id_ecdsa.pub. 2025-11-01 00:20:57.767010 | controller -> localhost | The key fingerprint is: 2025-11-01 00:20:57.767071 | controller -> localhost | SHA256:FtCgRTXWQy/u9H6W4w6x57w9chQvRN0th47ao6lWCzE zuul-build-sshkey 2025-11-01 00:20:57.767105 | controller -> localhost | The key's randomart image is: 2025-11-01 00:20:57.767124 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-01 00:20:57.767142 | controller -> localhost | | .=++o. oo| 2025-11-01 00:20:57.767159 | controller -> localhost | | o o..o. + =| 2025-11-01 00:20:57.767176 | controller -> localhost | | . . ...+ o | 2025-11-01 00:20:57.767193 | controller -> localhost | | Eo .. o. | 2025-11-01 00:20:57.767209 | controller -> localhost | | Sooo.. o| 2025-11-01 00:20:57.767226 | controller -> localhost | | ..oo.oo...| 2025-11-01 00:20:57.767242 | controller -> localhost | | o.++.oo | 2025-11-01 00:20:57.767258 | controller -> localhost | | . +. *=+ | 2025-11-01 00:20:57.767275 | controller -> localhost | | ... .=Ooo| 2025-11-01 00:20:57.767291 | controller -> localhost | +----[SHA256]-----+ 2025-11-01 00:20:57.767335 | controller -> localhost | ok: Runtime: 0:00:00.009183 2025-11-01 00:20:57.781418 | 2025-11-01 00:20:57.781539 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-01 00:20:57.811704 | controller | ok 2025-11-01 00:20:57.828187 | controller | included: /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-01 00:20:57.837216 | 2025-11-01 00:20:57.837289 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-01 00:20:57.861785 | controller | skipping: Conditional result was False 2025-11-01 00:20:57.872303 | 2025-11-01 00:20:57.872444 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-01 00:20:58.338396 | controller | changed 2025-11-01 00:20:58.345478 | 2025-11-01 00:20:58.345596 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-01 00:20:58.711412 | controller | ok 2025-11-01 00:20:58.726656 | 2025-11-01 00:20:58.726876 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-01 00:21:00.149226 | controller | changed 2025-11-01 00:21:00.157305 | 2025-11-01 00:21:00.157395 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-01 00:21:01.852848 | controller | changed 2025-11-01 00:21:01.866588 | 2025-11-01 00:21:01.866789 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-01 00:21:01.905253 | controller | skipping: Conditional result was False 2025-11-01 00:21:01.916647 | 2025-11-01 00:21:01.916817 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-01 00:21:02.204305 | controller -> localhost | changed 2025-11-01 00:21:02.217151 | 2025-11-01 00:21:02.217272 | TASK [add-build-sshkey : Add back temp key] 2025-11-01 00:21:02.517795 | controller -> localhost | Identity added: /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/work/0742b9c98fe84dbab2943cde3fcda4b1_id_ecdsa (zuul-build-sshkey) 2025-11-01 00:21:02.518600 | controller -> localhost | ok: Runtime: 0:00:00.010508 2025-11-01 00:21:02.527378 | 2025-11-01 00:21:02.527484 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-01 00:21:03.091133 | controller | ok 2025-11-01 00:21:03.097189 | 2025-11-01 00:21:03.097296 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-01 00:21:03.142734 | controller | skipping: Conditional result was False 2025-11-01 00:21:03.167819 | 2025-11-01 00:21:03.167965 | TASK [include_role : remove-zuul-sshkey] 2025-11-01 00:21:03.193717 | controller | skipping: Conditional result was False 2025-11-01 00:21:03.203750 | 2025-11-01 00:21:03.203914 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-01 00:21:03.750706 | controller | ok: "logs" 2025-11-01 00:21:03.751074 | controller | ok: All items complete 2025-11-01 00:21:03.751121 | 2025-11-01 00:21:04.093872 | controller | ok: "artifacts" 2025-11-01 00:21:04.500591 | controller | ok: "docs" 2025-11-01 00:21:04.510156 | 2025-11-01 00:21:04.510280 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-01 00:21:04.893653 | controller | changed: "logs" 2025-11-01 00:21:05.214674 | controller | changed: "artifacts" 2025-11-01 00:21:05.667808 | controller | changed: "docs" 2025-11-01 00:21:05.704727 | 2025-11-01 00:21:05.704905 | PLAY RECAP 2025-11-01 00:21:05.704957 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-01 00:21:05.704984 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-01 00:21:05.705001 | 2025-11-01 00:21:05.825156 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-01 00:21:05.826134 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-01 00:21:06.456387 | 2025-11-01 00:21:06.456519 | PLAY [all] 2025-11-01 00:21:06.480076 | 2025-11-01 00:21:06.480218 | TASK [Install binary dependencies] 2025-11-01 00:21:06.530687 | controller | ok 2025-11-01 00:21:06.551232 | 2025-11-01 00:21:06.551377 | TASK [bindep : Include find tasks] 2025-11-01 00:21:06.582844 | controller | ok 2025-11-01 00:21:06.590545 | controller | included: /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-01 00:21:06.597140 | 2025-11-01 00:21:06.597232 | TASK [bindep : Look for bindep.txt] 2025-11-01 00:21:07.126963 | controller | ok 2025-11-01 00:21:07.133335 | 2025-11-01 00:21:07.133414 | TASK [bindep : Define bindep_file fact] 2025-11-01 00:21:07.147728 | controller | skipping: Conditional result was False 2025-11-01 00:21:07.154493 | 2025-11-01 00:21:07.154577 | TASK [bindep : Look for other-requirements.txt] 2025-11-01 00:21:07.485117 | controller | ok 2025-11-01 00:21:07.495589 | 2025-11-01 00:21:07.495774 | TASK [bindep : Define bindep_file fact] 2025-11-01 00:21:07.543118 | controller | skipping: Conditional result was False 2025-11-01 00:21:07.554509 | 2025-11-01 00:21:07.554654 | TASK [bindep : Look for bindep fallback file] 2025-11-01 00:21:07.581623 | controller | skipping: Conditional result was False 2025-11-01 00:21:07.588727 | 2025-11-01 00:21:07.588849 | TASK [bindep : Define bindep_file fact] 2025-11-01 00:21:07.637715 | controller | skipping: Conditional result was False 2025-11-01 00:21:07.644384 | 2025-11-01 00:21:07.644499 | TASK [bindep : Include bindep tasks] 2025-11-01 00:21:07.668418 | controller | skipping: Conditional result was False 2025-11-01 00:21:07.676342 | 2025-11-01 00:21:07.676462 | TASK [bindep : Include install tasks] 2025-11-01 00:21:07.702424 | controller | skipping: Conditional result was False 2025-11-01 00:21:07.708422 | 2025-11-01 00:21:07.708503 | LOOP [bindep : Include package tasks] 2025-11-01 00:21:07.764042 | 2025-11-01 00:21:07.764204 | TASK [Run test-setup role] 2025-11-01 00:21:07.785053 | controller | ok 2025-11-01 00:21:07.804196 | 2025-11-01 00:21:07.804317 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-01 00:21:08.127054 | controller | ok 2025-11-01 00:21:08.133801 | 2025-11-01 00:21:08.133892 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-01 00:21:08.269136 | controller | skipping: Conditional result was False 2025-11-01 00:21:08.309214 | 2025-11-01 00:21:08.309317 | PLAY RECAP 2025-11-01 00:21:08.309371 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-01 00:21:08.309393 | 2025-11-01 00:21:08.419256 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-01 00:21:08.420169 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-01 00:21:09.030403 | 2025-11-01 00:21:09.030554 | PLAY [controller] 2025-11-01 00:21:09.050659 | 2025-11-01 00:21:09.050868 | TASK [Create the /root directory] 2025-11-01 00:21:09.793220 | controller | ok 2025-11-01 00:21:09.799145 | 2025-11-01 00:21:09.799247 | TASK [Install glibc-langpack-en] 2025-11-01 00:21:17.879658 | controller | ok: Nothing to do 2025-11-01 00:21:17.893270 | 2025-11-01 00:21:17.893466 | TASK [Ensure controller directory exists] 2025-11-01 00:21:18.374414 | controller | changed 2025-11-01 00:21:18.388654 | 2025-11-01 00:21:18.388877 | TASK [Install container runtime] 2025-11-01 00:21:18.462216 | controller | ok 2025-11-01 00:21:18.522073 | 2025-11-01 00:21:18.522221 | LOOP [ensure-podman : Find distribution installation] 2025-11-01 00:21:18.559846 | controller | ok: "/var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-01 00:21:18.566421 | controller | included: /var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-01 00:21:18.573947 | 2025-11-01 00:21:18.574060 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-01 00:22:34.827324 | controller | changed 2025-11-01 00:22:34.842960 | 2025-11-01 00:22:34.843174 | TASK [ensure-podman : Fetch podman version] 2025-11-01 00:22:35.611167 | controller | Client: Podman Engine 2025-11-01 00:22:35.611274 | controller | Version: 4.6.2 2025-11-01 00:22:35.611324 | controller | API Version: 4.6.2 2025-11-01 00:22:35.611363 | controller | Go Version: go1.19.12 2025-11-01 00:22:35.611436 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-01 00:22:35.611482 | controller | OS/Arch: linux/amd64 2025-11-01 00:22:35.989825 | controller | ok: Runtime: 0:00:00.227611 2025-11-01 00:22:36.004168 | 2025-11-01 00:22:36.004362 | TASK [ensure-podman : Print podman version installed] 2025-11-01 00:22:36.043767 | Podman version: Client: Podman Engine 2025-11-01 00:22:36.044168 | Version: 4.6.2 2025-11-01 00:22:36.044248 | API Version: 4.6.2 2025-11-01 00:22:36.044294 | Go Version: go1.19.12 2025-11-01 00:22:36.044333 | Built: Mon Aug 28 19:38:31 2023 2025-11-01 00:22:36.044373 | OS/Arch: linux/amd64 2025-11-01 00:22:36.056702 | 2025-11-01 00:22:36.056845 | TASK [ensure-podman : Validate podman engine] 2025-11-01 00:22:36.215479 | controller | skipping: Conditional result was False 2025-11-01 00:22:36.229833 | 2025-11-01 00:22:36.230010 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-01 00:22:36.256539 | controller | skipping: Conditional result was False 2025-11-01 00:22:36.268169 | 2025-11-01 00:22:36.268257 | TASK [Ensure python3.8 is present] 2025-11-01 00:22:36.291928 | controller | skipping: Conditional result was False 2025-11-01 00:22:36.297862 | 2025-11-01 00:22:36.297929 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-01 00:22:36.316411 | controller | ok 2025-11-01 00:22:36.335158 | 2025-11-01 00:22:36.335244 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-01 00:22:40.157785 | controller | ok: Nothing to do 2025-11-01 00:22:40.171820 | 2025-11-01 00:22:40.171983 | TASK [our-ensure-python : Also install python3-devel] 2025-11-01 00:22:53.383134 | controller | changed 2025-11-01 00:22:53.409137 | 2025-11-01 00:22:53.409284 | TASK [Run ensure-virtualenv role] 2025-11-01 00:22:53.431963 | controller | ok 2025-11-01 00:22:53.465718 | 2025-11-01 00:22:53.465841 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-01 00:22:53.866214 | controller | /usr/bin/virtualenv 2025-11-01 00:22:54.104152 | controller | ok: Runtime: 0:00:00.009560 2025-11-01 00:22:54.117424 | 2025-11-01 00:22:54.117566 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-01 00:22:54.152781 | controller | skipping: Conditional result was False 2025-11-01 00:22:54.153278 | controller | ok: All items complete 2025-11-01 00:22:54.153337 | 2025-11-01 00:22:54.179499 | 2025-11-01 00:22:54.179690 | TASK [Find the full path of the Python interpreter] 2025-11-01 00:22:54.615342 | controller | /usr/bin/python3 2025-11-01 00:22:54.919697 | controller | ok 2025-11-01 00:22:54.931599 | 2025-11-01 00:22:54.931736 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-01 00:22:56.352060 | controller | created virtual environment CPython3.11.0.final.0-64 in 773ms 2025-11-01 00:22:56.392184 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-01 00:22:56.392242 | 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-worker/.local/share/virtualenv) 2025-11-01 00:22:56.392261 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-01 00:22:56.392284 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-01 00:22:56.602245 | controller | changed 2025-11-01 00:22:56.615316 | 2025-11-01 00:22:56.615480 | TASK [Set selinux package] 2025-11-01 00:22:56.655361 | controller | ok 2025-11-01 00:22:56.666751 | 2025-11-01 00:22:56.666887 | TASK [Set selinux package (Fedora)] 2025-11-01 00:22:56.706937 | controller | ok 2025-11-01 00:22:56.720819 | 2025-11-01 00:22:56.721099 | TASK [Install selinux into virtualenv] 2025-11-01 00:22:59.369999 | controller | Collecting selinux-please-lie-to-me 2025-11-01 00:22:59.460209 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-01 00:22:59.993854 | controller | Collecting setuptools<50.0.0 2025-11-01 00:23:00.007862 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-01 00:23:00.110532 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 8.5 MB/s eta 0:00:00 2025-11-01 00:23:00.265914 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-01 00:23:00.266348 | controller | Attempting uninstall: setuptools 2025-11-01 00:23:00.271438 | controller | Found existing installation: setuptools 62.6.0 2025-11-01 00:23:00.383140 | controller | Uninstalling setuptools-62.6.0: 2025-11-01 00:23:00.398333 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-01 00:23:01.118686 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-01 00:23:01.329842 | controller | 2025-11-01 00:23:01.560009 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-01 00:23:01.560060 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-01 00:23:01.901336 | controller | ok: Runtime: 0:00:04.338784 2025-11-01 00:23:01.909456 | 2025-11-01 00:23:01.909619 | TASK [Install pytest-forked into virtualenv] 2025-11-01 00:23:03.443968 | controller | Collecting pytest-forked 2025-11-01 00:23:03.536246 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-01 00:23:03.597787 | controller | Collecting py 2025-11-01 00:23:03.612346 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-01 00:23:03.648959 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00 2025-11-01 00:23:03.928631 | controller | Collecting pytest>=3.10 2025-11-01 00:23:03.942887 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-11-01 00:23:04.007292 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.0 MB/s eta 0:00:00 2025-11-01 00:23:04.068892 | controller | Collecting iniconfig>=1 2025-11-01 00:23:04.083428 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-01 00:23:04.212959 | controller | Collecting packaging>=20 2025-11-01 00:23:04.227921 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-01 00:23:04.240884 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.1 MB/s eta 0:00:00 2025-11-01 00:23:04.316119 | controller | Collecting pluggy<2,>=1.5 2025-11-01 00:23:04.330346 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-01 00:23:04.407607 | controller | Collecting pygments>=2.7.2 2025-11-01 00:23:04.421820 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-01 00:23:04.550739 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.7 MB/s eta 0:00:00 2025-11-01 00:23:04.685061 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-01 00:23:06.950341 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0 2025-11-01 00:23:06.966412 | controller | 2025-11-01 00:23:07.154671 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-01 00:23:07.154716 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-01 00:23:07.597350 | controller | ok: Runtime: 0:00:04.721163 2025-11-01 00:23:07.610282 | 2025-11-01 00:23:07.610458 | TASK [Update pip] 2025-11-01 00:23:08.728800 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-01 00:23:09.000242 | controller | Collecting pip 2025-11-01 00:23:09.106593 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-01 00:23:09.286173 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.3 MB/s eta 0:00:00 2025-11-01 00:23:09.433560 | controller | Installing collected packages: pip 2025-11-01 00:23:09.434024 | controller | Attempting uninstall: pip 2025-11-01 00:23:09.438596 | controller | Found existing installation: pip 22.2.2 2025-11-01 00:23:09.696558 | controller | Uninstalling pip-22.2.2: 2025-11-01 00:23:09.726348 | controller | Successfully uninstalled pip-22.2.2 2025-11-01 00:23:11.569437 | controller | Successfully installed pip-25.3 2025-11-01 00:23:12.293651 | controller | ok: Runtime: 0:00:03.630630 2025-11-01 00:23:12.301592 | 2025-11-01 00:23:12.301689 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-01 00:23:12.879050 | controller | changed 2025-11-01 00:23:12.890654 | 2025-11-01 00:23:12.890806 | TASK [Install ansible into virtualenv] 2025-11-01 00:23:13.929039 | controller | Processing ./src/github.com/ansible/ansible 2025-11-01 00:23:13.935668 | controller | Installing build dependencies: started 2025-11-01 00:23:15.879458 | controller | Installing build dependencies: finished with status 'done' 2025-11-01 00:23:17.408629 | controller | Getting requirements to build wheel: started 2025-11-01 00:23:17.408694 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-01 00:23:17.410292 | controller | Preparing metadata (pyproject.toml): started 2025-11-01 00:23:18.340635 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-01 00:23:18.344909 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-11-01 00:23:18.344959 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-01 00:23:18.571848 | controller | ERROR 2025-11-01 00:23:18.572045 | controller | { 2025-11-01 00:23:18.572078 | controller | "delta": "0:00:05.132474", 2025-11-01 00:23:18.572097 | controller | "end": "2025-11-01 00:23:18.493554", 2025-11-01 00:23:18.572113 | controller | "msg": "non-zero return code", 2025-11-01 00:23:18.572141 | controller | "rc": 1, 2025-11-01 00:23:18.572157 | controller | "start": "2025-11-01 00:23:13.361080" 2025-11-01 00:23:18.572172 | controller | } failure 2025-11-01 00:23:18.574225 | 2025-11-01 00:23:18.574280 | PLAY RECAP 2025-11-01 00:23:18.574341 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-01 00:23:18.574364 | 2025-11-01 00:23:18.682995 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-01 00:23:18.685079 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-01 00:23:19.310419 | 2025-11-01 00:23:19.310534 | PLAY [all] 2025-11-01 00:23:19.332068 | 2025-11-01 00:23:19.332187 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-01 00:23:20.153637 | controller | changed: non-zero return code 2025-11-01 00:23:20.162538 | 2025-11-01 00:23:20.162687 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-01 00:23:20.178293 | controller | skipping: Conditional result was False 2025-11-01 00:23:20.185333 | 2025-11-01 00:23:20.185416 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-01 00:23:20.208708 | 2025-11-01 00:23:20.208880 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-01 00:23:20.229939 | 2025-11-01 00:23:20.230133 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-01 00:23:20.246704 | controller | skipping: Conditional result was False 2025-11-01 00:23:20.256230 | 2025-11-01 00:23:20.256379 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-01 00:23:20.286926 | 2025-11-01 00:23:20.287247 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-01 00:23:20.302508 | controller | skipping: Conditional result was False 2025-11-01 00:23:20.311239 | 2025-11-01 00:23:20.311381 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-01 00:23:20.326609 | controller | skipping: Conditional result was False 2025-11-01 00:23:20.336226 | 2025-11-01 00:23:20.336359 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-01 00:23:20.351946 | controller | skipping: Conditional result was False 2025-11-01 00:23:20.394715 | 2025-11-01 00:23:20.394838 | PLAY RECAP 2025-11-01 00:23:20.394892 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-01 00:23:20.394918 | 2025-11-01 00:23:20.518805 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-01 00:23:20.519735 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-01 00:23:21.157659 | 2025-11-01 00:23:21.157782 | PLAY [all:!appliance*] 2025-11-01 00:23:21.180054 | 2025-11-01 00:23:21.180192 | TASK [unregister the node] 2025-11-01 00:23:21.313075 | controller | skipping: Conditional result was False 2025-11-01 00:23:21.319219 | 2025-11-01 00:23:21.319313 | TASK [include_role : fetch-output] 2025-11-01 00:23:21.355785 | controller | ok 2025-11-01 00:23:21.397545 | 2025-11-01 00:23:21.397684 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-01 00:23:21.474156 | controller | skipping: Conditional result was False 2025-11-01 00:23:21.480778 | 2025-11-01 00:23:21.480868 | TASK [fetch-output : Set log path for single node] 2025-11-01 00:23:21.511744 | controller | ok 2025-11-01 00:23:21.518351 | 2025-11-01 00:23:21.518464 | LOOP [fetch-output : Ensure local output dirs] 2025-11-01 00:23:21.936988 | controller -> localhost | ok: "/var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/work/logs" 2025-11-01 00:23:22.163136 | controller -> localhost | changed: "/var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/work/artifacts" 2025-11-01 00:23:22.391361 | controller -> localhost | changed: "/var/lib/zuul/builds/0742b9c98fe84dbab2943cde3fcda4b1/work/docs" 2025-11-01 00:23:22.406664 | 2025-11-01 00:23:22.406745 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-01 00:23:23.714791 | controller | changed: 2025-11-01 00:23:23.715001 | controller | .d..t...... ./ 2025-11-01 00:23:23.715046 | controller | cd+++++++++ controller/ 2025-11-01 00:23:23.715079 | controller | changed: All items complete 2025-11-01 00:23:23.715099 | 2025-11-01 00:23:24.782077 | controller | changed: .d..t...... ./ 2025-11-01 00:23:25.837483 | controller | changed: .d..t...... ./ 2025-11-01 00:23:25.873652 | 2025-11-01 00:23:25.873978 | TASK [include_role : fetch-output-openshift] 2025-11-01 00:23:25.899468 | controller | skipping: Conditional result was False 2025-11-01 00:23:25.908439 | 2025-11-01 00:23:25.908553 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-01 00:23:25.957606 | controller | skipping: Conditional result was False 2025-11-01 00:23:25.975517 | controller | skipping: Conditional result was False 2025-11-01 00:23:26.042482 | 2025-11-01 00:23:26.042608 | PLAY [localhost] 2025-11-01 00:23:26.062612 | 2025-11-01 00:23:26.062770 | TASK [Run Zuul manifest role] 2025-11-01 00:23:26.083459 | localhost | ok 2025-11-01 00:23:26.102129 | 2025-11-01 00:23:26.102242 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-01 00:23:26.479988 | localhost | changed 2025-11-01 00:23:26.485661 | 2025-11-01 00:23:26.485739 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-01 00:23:26.529889 | localhost | ok 2025-11-01 00:23:26.548619 | 2025-11-01 00:23:26.548750 | TASK [Set zuul-log-path fact] 2025-11-01 00:23:26.570427 | localhost | ok 2025-11-01 00:23:26.589589 | 2025-11-01 00:23:26.589690 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-01 00:23:26.629850 | localhost | ok 2025-11-01 00:23:26.641934 | 2025-11-01 00:23:26.642041 | LOOP [Run upload-logs-swift role] 2025-11-01 00:23:26.686656 | localhost | Output suppressed because no_log was given 2025-11-01 00:23:26.723290 | 2025-11-01 00:23:26.723407 | TASK [Set zuul-log-path fact] 2025-11-01 00:23:26.748613 | localhost | skipping: Conditional result was False 2025-11-01 00:23:26.756288 | 2025-11-01 00:23:26.756393 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-01 00:23:27.177425 | localhost -> localhost | ok: Runtime: 0:00:00.005876 2025-11-01 00:23:27.187778 | 2025-11-01 00:23:27.187916 | TASK [upload-logs-swift : Upload logs to swift]