2025-10-23 00:17:47.253354 | Job console starting...
2025-10-23 00:17:47.265253 | Updating repositories
2025-10-23 00:17:47.434404 | Preparing job workspace
2025-10-23 00:17:51.453855 | Running Ansible setup...
2025-10-23 00:17:59.970277 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-23 00:18:00.770279 | 
2025-10-23 00:18:00.770415 | PLAY [localhost]
2025-10-23 00:18:00.780318 | 
2025-10-23 00:18:00.780438 | TASK [Gathering Facts]
2025-10-23 00:18:01.751359 | localhost | ok
2025-10-23 00:18:01.782994 | 
2025-10-23 00:18:01.783159 | TASK [Setup log path fact]
2025-10-23 00:18:01.808587 | localhost | ok
2025-10-23 00:18:01.827548 | 
2025-10-23 00:18:01.827670 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-23 00:18:01.870239 | localhost | ok
2025-10-23 00:18:01.881149 | 
2025-10-23 00:18:01.881241 | TASK [emit-job-header : Print job information]
2025-10-23 00:18:01.914752 | # Job Information
2025-10-23 00:18:01.914953 | Ansible Version: 2.15.12
2025-10-23 00:18:01.914995 | Job: ansible-test-sanity-docker-milestone
2025-10-23 00:18:01.915024 | Pipeline: periodic
2025-10-23 00:18:01.915049 | Executor: ze03.softwarefactory-project.io
2025-10-23 00:18:01.915072 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-23 00:18:01.915101 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/e12/ansible/e12396414b424b36883b37015054ffb7/
2025-10-23 00:18:01.915126 | Event ID: 0b277d6fb2034b3eb017dadc7a95f30f
2025-10-23 00:18:01.920539 | 
2025-10-23 00:18:01.920648 | LOOP [emit-job-header : Print node information]
2025-10-23 00:18:02.048186 | localhost | ok:
2025-10-23 00:18:02.048457 | localhost | # Node Information
2025-10-23 00:18:02.048496 | localhost | Inventory Hostname: controller
2025-10-23 00:18:02.048524 | localhost | Hostname: ip-172-16-82-173
2025-10-23 00:18:02.048550 | localhost | Username: zuul-worker
2025-10-23 00:18:02.048579 | localhost | Distro: Fedora 37
2025-10-23 00:18:02.048626 | localhost | Provider: ansible-us-east-2
2025-10-23 00:18:02.048651 | localhost | Region: us-east-2
2025-10-23 00:18:02.048676 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-23 00:18:02.048700 | localhost | Product Name: t3.small
2025-10-23 00:18:02.048742 | localhost | Interface IP: 3.19.219.33
2025-10-23 00:18:02.058798 | 
2025-10-23 00:18:02.058970 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-23 00:18:02.505817 | localhost -> localhost | changed
2025-10-23 00:18:02.513700 | 
2025-10-23 00:18:02.513842 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-23 00:18:03.378623 | localhost -> localhost | changed
2025-10-23 00:18:03.421876 | 
2025-10-23 00:18:03.422019 | PLAY [all:!appliance*]
2025-10-23 00:18:03.451874 | 
2025-10-23 00:18:03.452002 | TASK [include_role : start-zuul-console]
2025-10-23 00:18:03.474656 | controller | ok
2025-10-23 00:18:03.489891 | 
2025-10-23 00:18:03.490010 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-23 00:18:04.863598 | controller | ok
2025-10-23 00:18:04.874046 | 
2025-10-23 00:18:04.874120 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-23 00:18:07.106496 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-23 00:18:07.113234 | 
2025-10-23 00:18:07.113315 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-23 00:18:07.281494 | controller | skipping: Conditional result was False
2025-10-23 00:18:07.288078 | 
2025-10-23 00:18:07.288179 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-23 00:18:07.306237 | controller | skipping: Conditional result was False
2025-10-23 00:18:07.315100 | 
2025-10-23 00:18:07.315221 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-23 00:18:07.341278 | controller | skipping: Conditional result was False
2025-10-23 00:18:07.347422 | 
2025-10-23 00:18:07.347531 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-23 00:18:07.371787 | controller | skipping: Conditional result was False
2025-10-23 00:18:07.378115 | 
2025-10-23 00:18:07.378235 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-23 00:18:07.402395 | controller | skipping: Conditional result was False
2025-10-23 00:18:07.412428 | 
2025-10-23 00:18:07.412546 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-23 00:18:07.436963 | controller | skipping: Conditional result was False
2025-10-23 00:18:07.448013 | 
2025-10-23 00:18:07.448114 | TASK [Disable Fedora Modular]
2025-10-23 00:18:08.270892 | controller | changed
2025-10-23 00:18:08.279740 | 
2025-10-23 00:18:08.279856 | TASK [Enable EPEL]
2025-10-23 00:18:08.308017 | controller | skipping: Conditional result was False
2025-10-23 00:18:08.315642 | 
2025-10-23 00:18:08.315901 | TASK [Register the RHEL node]
2025-10-23 00:18:08.532076 | 
2025-10-23 00:18:08.532273 | TASK [Show the subscription-manager status]
2025-10-23 00:18:08.726056 | controller | skipping: Conditional result was False
2025-10-23 00:18:08.740817 | 
2025-10-23 00:18:08.740965 | TASK [Enable EPEL on RHEL]
2025-10-23 00:18:08.916823 | controller | skipping: Conditional result was False
2025-10-23 00:18:08.925309 | 
2025-10-23 00:18:08.925462 | TASK [Install git and tox]
2025-10-23 00:19:48.497588 | controller | changed
2025-10-23 00:19:48.506959 | 
2025-10-23 00:19:48.507083 | TASK [include_role : prepare-workspace]
2025-10-23 00:19:48.528258 | controller | ok
2025-10-23 00:19:48.556458 | 
2025-10-23 00:19:48.556604 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-23 00:19:49.164690 | controller | ok
2025-10-23 00:19:49.174902 | 
2025-10-23 00:19:49.175025 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-23 00:20:05.585179 | controller | Output suppressed because no_log was given
2025-10-23 00:20:05.634665 | 
2025-10-23 00:20:05.634835 | TASK [include_role : prepare-workspace-openshift]
2025-10-23 00:20:05.659014 | controller | skipping: Conditional result was False
2025-10-23 00:20:05.682465 | 
2025-10-23 00:20:05.682559 | PLAY [all:!appliance]
2025-10-23 00:20:05.700240 | 
2025-10-23 00:20:05.700347 | TASK [Run add-build-sshkey role (RSA)]
2025-10-23 00:20:05.732260 | controller | ok
2025-10-23 00:20:05.749594 | 
2025-10-23 00:20:05.749710 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-23 00:20:05.999215 | controller -> localhost | ok
2025-10-23 00:20:06.006544 | 
2025-10-23 00:20:06.006654 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-23 00:20:06.048168 | controller | ok
2025-10-23 00:20:06.079431 | controller | included: /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-23 00:20:06.085694 | 
2025-10-23 00:20:06.085798 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-23 00:20:06.609877 | controller -> localhost | Generating public/private rsa key pair.
2025-10-23 00:20:06.610108 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/work/e12396414b424b36883b37015054ffb7_id_rsa.
2025-10-23 00:20:06.610138 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/work/e12396414b424b36883b37015054ffb7_id_rsa.pub.
2025-10-23 00:20:06.610160 | controller -> localhost | The key fingerprint is:
2025-10-23 00:20:06.610189 | controller -> localhost | SHA256:EHNIoXUPPDwRKLykE7H+ygYLbXdXNZYNvv1qv2ByKVM zuul-build-sshkey
2025-10-23 00:20:06.610215 | controller -> localhost | The key's randomart image is:
2025-10-23 00:20:06.610234 | controller -> localhost | +---[RSA 2048]----+
2025-10-23 00:20:06.610252 | controller -> localhost | |  .o .***o  .+   |
2025-10-23 00:20:06.610270 | controller -> localhost | |  ..+oo==o .= .  |
2025-10-23 00:20:06.610287 | controller -> localhost | |  .+.o.  o.o..   |
2025-10-23 00:20:06.610305 | controller -> localhost | | .o .  .  .  o   |
2025-10-23 00:20:06.610322 | controller -> localhost | | ...    S.  .E.  |
2025-10-23 00:20:06.610348 | controller -> localhost | |o o.. . .   . .. |
2025-10-23 00:20:06.610369 | controller -> localhost | |.+ ... .   + =  .|
2025-10-23 00:20:06.610387 | controller -> localhost | |....        * o. |
2025-10-23 00:20:06.610405 | controller -> localhost | | .o          ..oo|
2025-10-23 00:20:06.610425 | controller -> localhost | +----[SHA256]-----+
2025-10-23 00:20:06.610475 | controller -> localhost | ok: Runtime: 0:00:00.081505
2025-10-23 00:20:06.617597 | 
2025-10-23 00:20:06.617694 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-23 00:20:06.639500 | controller | ok
2025-10-23 00:20:06.651879 | controller | included: /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-23 00:20:06.662249 | 
2025-10-23 00:20:06.662369 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-23 00:20:06.676571 | controller | skipping: Conditional result was False
2025-10-23 00:20:06.683624 | 
2025-10-23 00:20:06.683707 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-23 00:20:07.608879 | controller | changed
2025-10-23 00:20:07.614165 | 
2025-10-23 00:20:07.614234 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-23 00:20:08.161574 | controller | ok
2025-10-23 00:20:08.170158 | 
2025-10-23 00:20:08.170263 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-23 00:20:09.826796 | controller | changed
2025-10-23 00:20:09.837470 | 
2025-10-23 00:20:09.837614 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-23 00:20:11.343080 | controller | changed
2025-10-23 00:20:11.351876 | 
2025-10-23 00:20:11.352002 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-23 00:20:11.368071 | controller | skipping: Conditional result was False
2025-10-23 00:20:11.378504 | 
2025-10-23 00:20:11.378638 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-23 00:20:11.794882 | controller -> localhost | changed
2025-10-23 00:20:11.808005 | 
2025-10-23 00:20:11.808128 | TASK [add-build-sshkey : Add back temp key]
2025-10-23 00:20:12.138877 | controller -> localhost | Identity added: /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/work/e12396414b424b36883b37015054ffb7_id_rsa (zuul-build-sshkey)
2025-10-23 00:20:12.139065 | controller -> localhost | ok: Runtime: 0:00:00.031112
2025-10-23 00:20:12.145631 | 
2025-10-23 00:20:12.145744 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-23 00:20:12.687837 | controller | ok
2025-10-23 00:20:12.693907 | 
2025-10-23 00:20:12.693977 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-23 00:20:12.722127 | controller | skipping: Conditional result was False
2025-10-23 00:20:12.741476 | 
2025-10-23 00:20:12.741592 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-23 00:20:12.762795 | controller | ok
2025-10-23 00:20:12.778918 | 
2025-10-23 00:20:12.779008 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-23 00:20:13.029262 | controller -> localhost | ok
2025-10-23 00:20:13.039043 | 
2025-10-23 00:20:13.039256 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-23 00:20:13.062962 | controller | ok
2025-10-23 00:20:13.082900 | controller | included: /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-23 00:20:13.093095 | 
2025-10-23 00:20:13.093200 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-23 00:20:13.437402 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-23 00:20:13.437669 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/work/e12396414b424b36883b37015054ffb7_id_ecdsa.
2025-10-23 00:20:13.437703 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/work/e12396414b424b36883b37015054ffb7_id_ecdsa.pub.
2025-10-23 00:20:13.437771 | controller -> localhost | The key fingerprint is:
2025-10-23 00:20:13.437807 | controller -> localhost | SHA256:rMIgi4a3R6iNB5nRHmLokvC5M0WeSTNPOn8MX3K00Ss zuul-build-sshkey
2025-10-23 00:20:13.437832 | controller -> localhost | The key's randomart image is:
2025-10-23 00:20:13.437852 | controller -> localhost | +---[ECDSA 521]---+
2025-10-23 00:20:13.437873 | controller -> localhost | |                 |
2025-10-23 00:20:13.437900 | controller -> localhost | |                 |
2025-10-23 00:20:13.437923 | controller -> localhost | |..         .     |
2025-10-23 00:20:13.437945 | controller -> localhost | |=.o = ..  o .    |
2025-10-23 00:20:13.437967 | controller -> localhost | |=O.B O  S. o .   |
2025-10-23 00:20:13.437987 | controller -> localhost | |O+=oO o.. E .    |
2025-10-23 00:20:13.438005 | controller -> localhost | |=*.+oo.+ + .     |
2025-10-23 00:20:13.438022 | controller -> localhost | |+.*.... +        |
2025-10-23 00:20:13.438039 | controller -> localhost | | ..+   .         |
2025-10-23 00:20:13.438057 | controller -> localhost | +----[SHA256]-----+
2025-10-23 00:20:13.438112 | controller -> localhost | ok: Runtime: 0:00:00.012672
2025-10-23 00:20:13.444873 | 
2025-10-23 00:20:13.444998 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-23 00:20:13.487251 | controller | ok
2025-10-23 00:20:13.496827 | controller | included: /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-23 00:20:13.507509 | 
2025-10-23 00:20:13.507637 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-23 00:20:13.522659 | controller | skipping: Conditional result was False
2025-10-23 00:20:13.529424 | 
2025-10-23 00:20:13.529543 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-23 00:20:14.090456 | controller | changed
2025-10-23 00:20:14.099019 | 
2025-10-23 00:20:14.099158 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-23 00:20:14.517317 | controller | ok
2025-10-23 00:20:14.530800 | 
2025-10-23 00:20:14.530971 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-23 00:20:16.109846 | controller | changed
2025-10-23 00:20:16.119209 | 
2025-10-23 00:20:16.119394 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-23 00:20:17.706269 | controller | changed
2025-10-23 00:20:17.754507 | 
2025-10-23 00:20:17.754632 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-23 00:20:17.779209 | controller | skipping: Conditional result was False
2025-10-23 00:20:17.786950 | 
2025-10-23 00:20:17.787068 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-23 00:20:18.087416 | controller -> localhost | changed
2025-10-23 00:20:18.107764 | 
2025-10-23 00:20:18.107930 | TASK [add-build-sshkey : Add back temp key]
2025-10-23 00:20:18.372962 | controller -> localhost | Identity added: /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/work/e12396414b424b36883b37015054ffb7_id_ecdsa (zuul-build-sshkey)
2025-10-23 00:20:18.373166 | controller -> localhost | ok: Runtime: 0:00:00.007403
2025-10-23 00:20:18.379860 | 
2025-10-23 00:20:18.379949 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-23 00:20:18.795841 | controller | ok
2025-10-23 00:20:18.809265 | 
2025-10-23 00:20:18.809428 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-23 00:20:18.836418 | controller | skipping: Conditional result was False
2025-10-23 00:20:18.861314 | 
2025-10-23 00:20:18.861495 | TASK [include_role : remove-zuul-sshkey]
2025-10-23 00:20:18.879627 | controller | skipping: Conditional result was False
2025-10-23 00:20:18.893442 | 
2025-10-23 00:20:18.893618 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-23 00:20:19.353930 | controller | ok: "logs"
2025-10-23 00:20:19.354328 | controller | ok: All items complete
2025-10-23 00:20:19.354392 | 
2025-10-23 00:20:19.772939 | controller | ok: "artifacts"
2025-10-23 00:20:20.129351 | controller | ok: "docs"
2025-10-23 00:20:20.139700 | 
2025-10-23 00:20:20.139895 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-23 00:20:20.680499 | controller | changed: "logs"
2025-10-23 00:20:21.036203 | controller | changed: "artifacts"
2025-10-23 00:20:21.389230 | controller | changed: "docs"
2025-10-23 00:20:21.418449 | 
2025-10-23 00:20:21.418534 | PLAY RECAP
2025-10-23 00:20:21.418578 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-23 00:20:21.418603 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-23 00:20:21.418621 | 
2025-10-23 00:20:21.527214 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-23 00:20:21.528077 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-23 00:20:22.092441 | 
2025-10-23 00:20:22.092562 | PLAY [all]
2025-10-23 00:20:22.114990 | 
2025-10-23 00:20:22.115128 | TASK [Install binary dependencies]
2025-10-23 00:20:22.166122 | controller | ok
2025-10-23 00:20:22.188594 | 
2025-10-23 00:20:22.188800 | TASK [bindep : Include find tasks]
2025-10-23 00:20:22.219869 | controller | ok
2025-10-23 00:20:22.229091 | controller | included: /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-23 00:20:22.235406 | 
2025-10-23 00:20:22.235479 | TASK [bindep : Look for bindep.txt]
2025-10-23 00:20:22.842452 | controller | ok
2025-10-23 00:20:22.849121 | 
2025-10-23 00:20:22.849254 | TASK [bindep : Define bindep_file fact]
2025-10-23 00:20:22.874444 | controller | skipping: Conditional result was False
2025-10-23 00:20:22.880984 | 
2025-10-23 00:20:22.881111 | TASK [bindep : Look for other-requirements.txt]
2025-10-23 00:20:23.353514 | controller | ok
2025-10-23 00:20:23.361702 | 
2025-10-23 00:20:23.361872 | TASK [bindep : Define bindep_file fact]
2025-10-23 00:20:23.386955 | controller | skipping: Conditional result was False
2025-10-23 00:20:23.396038 | 
2025-10-23 00:20:23.396185 | TASK [bindep : Look for bindep fallback file]
2025-10-23 00:20:23.422508 | controller | skipping: Conditional result was False
2025-10-23 00:20:23.433112 | 
2025-10-23 00:20:23.433252 | TASK [bindep : Define bindep_file fact]
2025-10-23 00:20:23.458297 | controller | skipping: Conditional result was False
2025-10-23 00:20:23.469018 | 
2025-10-23 00:20:23.469143 | TASK [bindep : Include bindep tasks]
2025-10-23 00:20:23.494195 | controller | skipping: Conditional result was False
2025-10-23 00:20:23.502553 | 
2025-10-23 00:20:23.502684 | TASK [bindep : Include install tasks]
2025-10-23 00:20:23.528374 | controller | skipping: Conditional result was False
2025-10-23 00:20:23.535093 | 
2025-10-23 00:20:23.535209 | LOOP [bindep : Include package tasks]
2025-10-23 00:20:23.602542 | 
2025-10-23 00:20:23.602697 | TASK [Run test-setup role]
2025-10-23 00:20:23.623172 | controller | ok
2025-10-23 00:20:23.645451 | 
2025-10-23 00:20:23.645576 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-23 00:20:23.997462 | controller | ok
2025-10-23 00:20:24.007333 | 
2025-10-23 00:20:24.007439 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-23 00:20:24.144140 | controller | skipping: Conditional result was False
2025-10-23 00:20:24.171631 | 
2025-10-23 00:20:24.171733 | PLAY RECAP
2025-10-23 00:20:24.171810 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-23 00:20:24.171836 | 
2025-10-23 00:20:24.292091 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-23 00:20:24.293042 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-23 00:20:24.914587 | 
2025-10-23 00:20:24.914726 | PLAY [controller]
2025-10-23 00:20:24.938235 | 
2025-10-23 00:20:24.938363 | TASK [Create the /root directory]
2025-10-23 00:20:26.121228 | controller | ok
2025-10-23 00:20:26.134867 | 
2025-10-23 00:20:26.135068 | TASK [Install glibc-langpack-en]
2025-10-23 00:20:34.249975 | controller | ok: Nothing to do
2025-10-23 00:20:34.262898 | 
2025-10-23 00:20:34.263090 | TASK [Ensure controller directory exists]
2025-10-23 00:20:34.719823 | controller | changed
2025-10-23 00:20:34.732255 | 
2025-10-23 00:20:34.732434 | TASK [Install container runtime]
2025-10-23 00:20:34.792489 | controller | ok
2025-10-23 00:20:34.853942 | 
2025-10-23 00:20:34.854086 | LOOP [ensure-podman : Find distribution installation]
2025-10-23 00:20:34.894263 | controller | ok: "/var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-23 00:20:34.916981 | controller | included: /var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-23 00:20:34.932585 | 
2025-10-23 00:20:34.933159 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-23 00:22:13.161563 | controller | changed
2025-10-23 00:22:13.170531 | 
2025-10-23 00:22:13.170660 | TASK [ensure-podman : Fetch podman version]
2025-10-23 00:22:13.995609 | controller | Client:       Podman Engine
2025-10-23 00:22:14.038570 | controller | Version:      4.6.2
2025-10-23 00:22:14.038623 | controller | API Version:  4.6.2
2025-10-23 00:22:14.038632 | controller | Go Version:   go1.19.12
2025-10-23 00:22:14.038655 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-23 00:22:14.038665 | controller | OS/Arch:      linux/amd64
2025-10-23 00:22:14.317569 | controller | ok: Runtime: 0:00:00.306616
2025-10-23 00:22:14.324037 | 
2025-10-23 00:22:14.324116 | TASK [ensure-podman : Print podman version installed]
2025-10-23 00:22:14.353637 | Podman version: Client:       Podman Engine
2025-10-23 00:22:14.353808 | Version:      4.6.2
2025-10-23 00:22:14.353840 | API Version:  4.6.2
2025-10-23 00:22:14.353860 | Go Version:   go1.19.12
2025-10-23 00:22:14.353879 | Built:        Mon Aug 28 19:38:31 2023
2025-10-23 00:22:14.353900 | OS/Arch:      linux/amd64
2025-10-23 00:22:14.359616 | 
2025-10-23 00:22:14.359679 | TASK [ensure-podman : Validate podman engine]
2025-10-23 00:22:14.514008 | controller | skipping: Conditional result was False
2025-10-23 00:22:14.533490 | 
2025-10-23 00:22:14.533683 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-23 00:22:14.552400 | controller | skipping: Conditional result was False
2025-10-23 00:22:14.581547 | 
2025-10-23 00:22:14.581716 | TASK [Ensure python3.8 is present]
2025-10-23 00:22:14.597631 | controller | skipping: Conditional result was False
2025-10-23 00:22:14.608668 | 
2025-10-23 00:22:14.608833 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-23 00:22:14.631039 | controller | ok
2025-10-23 00:22:14.658087 | 
2025-10-23 00:22:14.658203 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-23 00:22:18.378227 | controller | ok: Nothing to do
2025-10-23 00:22:18.383911 | 
2025-10-23 00:22:18.384038 | TASK [our-ensure-python : Also install python3-devel]
2025-10-23 00:22:32.175579 | controller | changed
2025-10-23 00:22:32.193854 | 
2025-10-23 00:22:32.194072 | TASK [Run ensure-virtualenv role]
2025-10-23 00:22:32.219589 | controller | ok
2025-10-23 00:22:32.263146 | 
2025-10-23 00:22:32.263353 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-23 00:22:32.714955 | controller | /usr/bin/virtualenv
2025-10-23 00:22:32.921866 | controller | ok: Runtime: 0:00:00.004610
2025-10-23 00:22:32.928106 | 
2025-10-23 00:22:32.928217 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-23 00:22:32.962821 | controller | skipping: Conditional result was False
2025-10-23 00:22:32.963188 | controller | ok: All items complete
2025-10-23 00:22:32.963235 | 
2025-10-23 00:22:32.979399 | 
2025-10-23 00:22:32.979536 | TASK [Find the full path of the Python interpreter]
2025-10-23 00:22:33.479127 | controller | /usr/bin/python3
2025-10-23 00:22:33.656397 | controller | ok
2025-10-23 00:22:33.685094 | 
2025-10-23 00:22:33.685227 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-23 00:22:35.665877 | controller | created virtual environment CPython3.11.0.final.0-64 in 730ms
2025-10-23 00:22:35.710567 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-23 00:22:35.710625 | 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-10-23 00:22:35.710640 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-23 00:22:35.710664 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-23 00:22:35.864918 | controller | changed
2025-10-23 00:22:35.873962 | 
2025-10-23 00:22:35.874094 | TASK [Set selinux package]
2025-10-23 00:22:35.897684 | controller | ok
2025-10-23 00:22:35.905622 | 
2025-10-23 00:22:35.905944 | TASK [Set selinux package (Fedora)]
2025-10-23 00:22:35.939096 | controller | ok
2025-10-23 00:22:35.944802 | 
2025-10-23 00:22:35.944922 | TASK [Install selinux into virtualenv]
2025-10-23 00:22:38.539944 | controller | Collecting selinux-please-lie-to-me
2025-10-23 00:22:38.637347 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-23 00:22:39.163279 | controller | Collecting setuptools<50.0.0
2025-10-23 00:22:39.176435 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-23 00:22:39.318671 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.0 MB/s eta 0:00:00
2025-10-23 00:22:39.472429 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-23 00:22:39.472765 | controller |   Attempting uninstall: setuptools
2025-10-23 00:22:39.477656 | controller |     Found existing installation: setuptools 62.6.0
2025-10-23 00:22:39.588549 | controller |     Uninstalling setuptools-62.6.0:
2025-10-23 00:22:39.603799 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-23 00:22:40.383153 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-23 00:22:40.587097 | controller |
2025-10-23 00:22:40.804790 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-23 00:22:40.804835 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-23 00:22:41.131164 | controller | ok: Runtime: 0:00:04.422853
2025-10-23 00:22:41.140878 | 
2025-10-23 00:22:41.141028 | TASK [Install pytest-forked into virtualenv]
2025-10-23 00:22:42.363099 | controller | Collecting pytest-forked
2025-10-23 00:22:42.451435 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-23 00:22:42.520566 | controller | Collecting py
2025-10-23 00:22:42.534123 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-23 00:22:42.570191 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00
2025-10-23 00:22:42.742783 | controller | Collecting pytest>=3.10
2025-10-23 00:22:42.756354 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-23 00:22:42.820957 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.9 MB/s eta 0:00:00
2025-10-23 00:22:42.876827 | controller | Collecting iniconfig>=1
2025-10-23 00:22:42.890646 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-23 00:22:42.957422 | controller | Collecting packaging>=20
2025-10-23 00:22:42.971483 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-23 00:22:42.983644 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.1 MB/s eta 0:00:00
2025-10-23 00:22:43.031607 | controller | Collecting pluggy<2,>=1.5
2025-10-23 00:22:43.045361 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-23 00:22:43.119576 | controller | Collecting pygments>=2.7.2
2025-10-23 00:22:43.133177 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-23 00:22:43.260229 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.9 MB/s eta 0:00:00
2025-10-23 00:22:43.395431 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-23 00:22:45.667810 | 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-10-23 00:22:45.684083 | controller |
2025-10-23 00:22:45.876629 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-23 00:22:45.876665 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-23 00:22:46.321580 | controller | ok: Runtime: 0:00:04.243832
2025-10-23 00:22:46.332581 | 
2025-10-23 00:22:46.332762 | TASK [Update pip]
2025-10-23 00:22:47.489621 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-23 00:22:47.728043 | controller | Collecting pip
2025-10-23 00:22:47.823884 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-23 00:22:48.030581 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.7 MB/s eta 0:00:00
2025-10-23 00:22:48.155105 | controller | Installing collected packages: pip
2025-10-23 00:22:48.155531 | controller |   Attempting uninstall: pip
2025-10-23 00:22:48.160133 | controller |     Found existing installation: pip 22.2.2
2025-10-23 00:22:48.418769 | controller |     Uninstalling pip-22.2.2:
2025-10-23 00:22:48.449146 | controller |       Successfully uninstalled pip-22.2.2
2025-10-23 00:22:50.166446 | controller | Successfully installed pip-25.2
2025-10-23 00:22:50.492037 | controller | ok: Runtime: 0:00:03.505685
2025-10-23 00:22:50.500473 | 
2025-10-23 00:22:50.500616 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-23 00:22:51.040546 | controller | changed
2025-10-23 00:22:51.054032 | 
2025-10-23 00:22:51.054218 | TASK [Install ansible into virtualenv]
2025-10-23 00:22:52.149670 | controller | Processing ./src/github.com/ansible/ansible
2025-10-23 00:22:52.156208 | controller |   Installing build dependencies: started
2025-10-23 00:22:54.136801 | controller |   Installing build dependencies: finished with status 'done'
2025-10-23 00:22:55.683569 | controller |   Getting requirements to build wheel: started
2025-10-23 00:22:55.683634 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-23 00:22:56.621562 | controller |   Preparing metadata (pyproject.toml): started
2025-10-23 00:22:56.621615 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-23 00:22:56.626578 | 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-10-23 00:22:56.631438 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-23 00:22:57.215165 | controller | ERROR
2025-10-23 00:22:57.215364 | controller | {
2025-10-23 00:22:57.215404 | controller |   "delta": "0:00:05.273008",
2025-10-23 00:22:57.215462 | controller |   "end": "2025-10-23 00:22:56.786112",
2025-10-23 00:22:57.215489 | controller |   "msg": "non-zero return code",
2025-10-23 00:22:57.215523 | controller |   "rc": 1,
2025-10-23 00:22:57.215546 | controller |   "start": "2025-10-23 00:22:51.513104"
2025-10-23 00:22:57.215567 | controller | }
failure
2025-10-23 00:22:57.217629 | 
2025-10-23 00:22:57.217696 | PLAY RECAP
2025-10-23 00:22:57.217774 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-23 00:22:57.217810 | 
2025-10-23 00:22:57.348827 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-23 00:22:57.349711 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-23 00:22:58.029081 | 
2025-10-23 00:22:58.029224 | PLAY [all]
2025-10-23 00:22:58.056756 | 
2025-10-23 00:22:58.056918 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-23 00:22:58.900196 | controller | changed: non-zero return code
2025-10-23 00:22:58.912882 | 
2025-10-23 00:22:58.913078 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-23 00:22:58.929791 | controller | skipping: Conditional result was False
2025-10-23 00:22:58.941371 | 
2025-10-23 00:22:58.941533 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-23 00:22:58.966779 | 
2025-10-23 00:22:58.967005 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-23 00:22:58.992364 | 
2025-10-23 00:22:58.992583 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-23 00:22:59.019313 | controller | skipping: Conditional result was False
2025-10-23 00:22:59.030039 | 
2025-10-23 00:22:59.030207 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-23 00:22:59.054250 | 
2025-10-23 00:22:59.054440 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-23 00:22:59.068474 | controller | skipping: Conditional result was False
2025-10-23 00:22:59.074943 | 
2025-10-23 00:22:59.075023 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-23 00:22:59.099259 | controller | skipping: Conditional result was False
2025-10-23 00:22:59.106002 | 
2025-10-23 00:22:59.106095 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-23 00:22:59.130848 | controller | skipping: Conditional result was False
2025-10-23 00:22:59.168259 | 
2025-10-23 00:22:59.168382 | PLAY RECAP
2025-10-23 00:22:59.168428 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-23 00:22:59.168448 | 
2025-10-23 00:22:59.279049 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-23 00:22:59.280211 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-23 00:22:59.933606 | 
2025-10-23 00:22:59.933717 | PLAY [all:!appliance*]
2025-10-23 00:22:59.954343 | 
2025-10-23 00:22:59.954450 | TASK [unregister the node]
2025-10-23 00:23:00.090598 | controller | skipping: Conditional result was False
2025-10-23 00:23:00.098940 | 
2025-10-23 00:23:00.099099 | TASK [include_role : fetch-output]
2025-10-23 00:23:00.132753 | controller | ok
2025-10-23 00:23:00.160164 | 
2025-10-23 00:23:00.160311 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-23 00:23:00.237284 | controller | skipping: Conditional result was False
2025-10-23 00:23:00.250889 | 
2025-10-23 00:23:00.251083 | TASK [fetch-output : Set log path for single node]
2025-10-23 00:23:00.289804 | controller | ok
2025-10-23 00:23:00.302065 | 
2025-10-23 00:23:00.302225 | LOOP [fetch-output : Ensure local output dirs]
2025-10-23 00:23:00.788667 | controller -> localhost | ok: "/var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/work/logs"
2025-10-23 00:23:01.120987 | controller -> localhost | changed: "/var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/work/artifacts"
2025-10-23 00:23:01.344830 | controller -> localhost | changed: "/var/lib/zuul/builds/e12396414b424b36883b37015054ffb7/work/docs"
2025-10-23 00:23:01.359122 | 
2025-10-23 00:23:01.359247 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-23 00:23:02.611634 | controller | changed:
2025-10-23 00:23:02.612016 | controller | .d..t...... ./
2025-10-23 00:23:02.612080 | controller | cd+++++++++ controller/
2025-10-23 00:23:02.612151 | controller | changed: All items complete
2025-10-23 00:23:02.612231 | 
2025-10-23 00:23:03.685395 | controller | changed: .d..t...... ./
2025-10-23 00:23:04.792289 | controller | changed: .d..t...... ./
2025-10-23 00:23:04.810336 | 
2025-10-23 00:23:04.810481 | TASK [include_role : fetch-output-openshift]
2025-10-23 00:23:04.834693 | controller | skipping: Conditional result was False
2025-10-23 00:23:04.842567 | 
2025-10-23 00:23:04.842666 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-23 00:23:04.870054 | controller | skipping: Conditional result was False
2025-10-23 00:23:04.879582 | controller | skipping: Conditional result was False
2025-10-23 00:23:04.915297 | 
2025-10-23 00:23:04.915407 | PLAY [localhost]
2025-10-23 00:23:04.928384 | 
2025-10-23 00:23:04.928487 | TASK [Run Zuul manifest role]
2025-10-23 00:23:04.947606 | localhost | ok
2025-10-23 00:23:04.964717 | 
2025-10-23 00:23:04.964876 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-23 00:23:05.365480 | localhost | changed
2025-10-23 00:23:05.372679 | 
2025-10-23 00:23:05.373017 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-23 00:23:05.403557 | localhost | ok
2025-10-23 00:23:05.412645 | 
2025-10-23 00:23:05.412801 | TASK [Set zuul-log-path fact]
2025-10-23 00:23:05.431106 | localhost | ok
2025-10-23 00:23:05.445502 | 
2025-10-23 00:23:05.445619 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-23 00:23:05.474195 | localhost | ok
2025-10-23 00:23:05.483605 | 
2025-10-23 00:23:05.483717 | LOOP [Run upload-logs-swift role]
2025-10-23 00:23:05.507492 | localhost | Output suppressed because no_log was given
2025-10-23 00:23:05.535501 | 
2025-10-23 00:23:05.535619 | TASK [Set zuul-log-path fact]
2025-10-23 00:23:05.560088 | localhost | skipping: Conditional result was False
2025-10-23 00:23:05.566218 | 
2025-10-23 00:23:05.566377 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-23 00:23:06.050284 | localhost -> localhost | ok: Runtime: 0:00:00.010083
2025-10-23 00:23:06.057576 | 
2025-10-23 00:23:06.057681 | TASK [upload-logs-swift : Upload logs to swift]