2025-09-25 00:12:14.761062 | Job console starting...
2025-09-25 00:12:14.773545 | Updating repositories
2025-09-25 00:12:15.384067 | Preparing job workspace
2025-09-25 00:12:19.097831 | Running Ansible setup...
2025-09-25 00:12:24.939342 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-25 00:12:25.530477 | 
2025-09-25 00:12:25.530667 | PLAY [localhost]
2025-09-25 00:12:25.539305 | 
2025-09-25 00:12:25.539375 | TASK [Gathering Facts]
2025-09-25 00:12:26.503406 | localhost | ok
2025-09-25 00:12:26.535164 | 
2025-09-25 00:12:26.535342 | TASK [Setup log path fact]
2025-09-25 00:12:26.555712 | localhost | ok
2025-09-25 00:12:26.574908 | 
2025-09-25 00:12:26.575053 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-25 00:12:26.624551 | localhost | ok
2025-09-25 00:12:26.632615 | 
2025-09-25 00:12:26.632715 | TASK [emit-job-header : Print job information]
2025-09-25 00:12:26.671135 | # Job Information
2025-09-25 00:12:26.671292 | Ansible Version: 2.15.12
2025-09-25 00:12:26.671323 | Job: ansible-test-sanity-docker-devel
2025-09-25 00:12:26.671343 | Pipeline: periodic
2025-09-25 00:12:26.671361 | Executor: ze01.softwarefactory-project.io
2025-09-25 00:12:26.671379 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-25 00:12:26.671401 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/644/ansible/6443590069a542fcb4e934c80bcf51cb/
2025-09-25 00:12:26.671419 | Event ID: 21226ec8c3ac40f2b6f018dec2056d83
2025-09-25 00:12:26.675407 | 
2025-09-25 00:12:26.675481 | LOOP [emit-job-header : Print node information]
2025-09-25 00:12:26.778570 | localhost | ok:
2025-09-25 00:12:26.778802 | localhost | # Node Information
2025-09-25 00:12:26.778830 | localhost | Inventory Hostname: controller
2025-09-25 00:12:26.778849 | localhost | Hostname: ip-172-16-0-202
2025-09-25 00:12:26.778867 | localhost | Username: zuul-worker
2025-09-25 00:12:26.778887 | localhost | Distro: Fedora 37
2025-09-25 00:12:26.778905 | localhost | Provider: ansible-us-east-2
2025-09-25 00:12:26.778921 | localhost | Region: us-east-2
2025-09-25 00:12:26.778937 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-25 00:12:26.778953 | localhost | Product Name: t3.small
2025-09-25 00:12:26.778969 | localhost | Interface IP: 3.15.190.179
2025-09-25 00:12:26.788345 | 
2025-09-25 00:12:26.788427 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-25 00:12:27.192046 | localhost -> localhost | changed
2025-09-25 00:12:27.198034 | 
2025-09-25 00:12:27.198127 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-25 00:12:28.046884 | localhost -> localhost | changed
2025-09-25 00:12:28.068979 | 
2025-09-25 00:12:28.069065 | PLAY [all:!appliance*]
2025-09-25 00:12:28.084233 | 
2025-09-25 00:12:28.084336 | TASK [include_role : start-zuul-console]
2025-09-25 00:12:28.102699 | controller | ok
2025-09-25 00:12:28.115449 | 
2025-09-25 00:12:28.115531 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-25 00:12:28.772614 | controller | ok
2025-09-25 00:12:28.812161 | 
2025-09-25 00:12:28.812280 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-25 00:12:30.358137 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-25 00:12:30.373938 | 
2025-09-25 00:12:30.374199 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-25 00:12:30.531157 | controller | skipping: Conditional result was False
2025-09-25 00:12:30.543778 | 
2025-09-25 00:12:30.543914 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-25 00:12:30.572044 | controller | skipping: Conditional result was False
2025-09-25 00:12:30.585575 | 
2025-09-25 00:12:30.585730 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-25 00:12:30.612992 | controller | skipping: Conditional result was False
2025-09-25 00:12:30.627354 | 
2025-09-25 00:12:30.627622 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-25 00:12:30.656657 | controller | skipping: Conditional result was False
2025-09-25 00:12:30.671156 | 
2025-09-25 00:12:30.671328 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-25 00:12:30.708398 | controller | skipping: Conditional result was False
2025-09-25 00:12:30.722405 | 
2025-09-25 00:12:30.722549 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-25 00:12:30.750402 | controller | skipping: Conditional result was False
2025-09-25 00:12:30.777294 | 
2025-09-25 00:12:30.777471 | TASK [Disable Fedora Modular]
2025-09-25 00:12:31.552749 | controller | changed
2025-09-25 00:12:31.564492 | 
2025-09-25 00:12:31.564619 | TASK [Enable EPEL]
2025-09-25 00:12:31.591960 | controller | skipping: Conditional result was False
2025-09-25 00:12:31.605058 | 
2025-09-25 00:12:31.605210 | TASK [Register the RHEL node]
2025-09-25 00:12:31.766420 | 
2025-09-25 00:12:31.766731 | TASK [Show the subscription-manager status]
2025-09-25 00:12:31.909731 | controller | skipping: Conditional result was False
2025-09-25 00:12:31.959304 | 
2025-09-25 00:12:31.959432 | TASK [Enable EPEL on RHEL]
2025-09-25 00:12:32.106082 | controller | skipping: Conditional result was False
2025-09-25 00:12:32.119953 | 
2025-09-25 00:12:32.120118 | TASK [Install git and tox]
2025-09-25 00:14:16.407874 | controller | changed
2025-09-25 00:14:16.422986 | 
2025-09-25 00:14:16.423228 | TASK [include_role : prepare-workspace]
2025-09-25 00:14:16.461296 | controller | ok
2025-09-25 00:14:16.497340 | 
2025-09-25 00:14:16.497532 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-25 00:14:17.155704 | controller | ok
2025-09-25 00:14:17.171256 | 
2025-09-25 00:14:17.171409 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-25 00:14:30.404780 | controller | Output suppressed because no_log was given
2025-09-25 00:14:30.419205 | 
2025-09-25 00:14:30.419312 | TASK [include_role : prepare-workspace-openshift]
2025-09-25 00:14:30.449313 | controller | skipping: Conditional result was False
2025-09-25 00:14:30.470099 | 
2025-09-25 00:14:30.470152 | PLAY [all:!appliance]
2025-09-25 00:14:30.485490 | 
2025-09-25 00:14:30.485547 | TASK [Run add-build-sshkey role (RSA)]
2025-09-25 00:14:30.515648 | controller | ok
2025-09-25 00:14:30.530746 | 
2025-09-25 00:14:30.530815 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-25 00:14:30.819960 | controller -> localhost | ok
2025-09-25 00:14:30.833897 | 
2025-09-25 00:14:30.834070 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-25 00:14:30.924766 | controller | ok
2025-09-25 00:14:30.949937 | controller | included: /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-25 00:14:30.958229 | 
2025-09-25 00:14:30.958350 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-25 00:14:31.411658 | controller -> localhost | Generating public/private rsa key pair.
2025-09-25 00:14:31.411906 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/work/6443590069a542fcb4e934c80bcf51cb_id_rsa.
2025-09-25 00:14:31.411946 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/work/6443590069a542fcb4e934c80bcf51cb_id_rsa.pub.
2025-09-25 00:14:31.411975 | controller -> localhost | The key fingerprint is:
2025-09-25 00:14:31.412003 | controller -> localhost | SHA256:vWLnmhbcoAkMiCYM+atpqYjjP4vbv55BVI5iCoEl2bg zuul-build-sshkey
2025-09-25 00:14:31.412071 | controller -> localhost | The key's randomart image is:
2025-09-25 00:14:31.412099 | controller -> localhost | +---[RSA 2048]----+
2025-09-25 00:14:31.412124 | controller -> localhost | |OB.    .         |
2025-09-25 00:14:31.412150 | controller -> localhost | |O=o   +          |
2025-09-25 00:14:31.412175 | controller -> localhost | |+o = o .         |
2025-09-25 00:14:31.412199 | controller -> localhost | |E + =   ..       |
2025-09-25 00:14:31.412223 | controller -> localhost | | . . o +So.      |
2025-09-25 00:14:31.412256 | controller -> localhost | |  . . o o ..     |
2025-09-25 00:14:31.412308 | controller -> localhost | | o.  .  o.o      |
2025-09-25 00:14:31.412337 | controller -> localhost | |*oo.  o..=       |
2025-09-25 00:14:31.412362 | controller -> localhost | |B=o+==..o..      |
2025-09-25 00:14:31.412391 | controller -> localhost | +----[SHA256]-----+
2025-09-25 00:14:31.412496 | controller -> localhost | ok: Runtime: 0:00:00.043718
2025-09-25 00:14:31.421222 | 
2025-09-25 00:14:31.421305 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-25 00:14:31.453299 | controller | ok
2025-09-25 00:14:31.466937 | controller | included: /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-25 00:14:31.479057 | 
2025-09-25 00:14:31.479140 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-25 00:14:31.504088 | controller | skipping: Conditional result was False
2025-09-25 00:14:31.512710 | 
2025-09-25 00:14:31.512905 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-25 00:14:32.100246 | controller | changed
2025-09-25 00:14:32.114080 | 
2025-09-25 00:14:32.114275 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-25 00:14:32.474229 | controller | ok
2025-09-25 00:14:32.487828 | 
2025-09-25 00:14:32.487983 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-25 00:14:33.809977 | controller | changed
2025-09-25 00:14:33.820108 | 
2025-09-25 00:14:33.820196 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-25 00:14:35.122627 | controller | changed
2025-09-25 00:14:35.135468 | 
2025-09-25 00:14:35.135603 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-25 00:14:35.163830 | controller | skipping: Conditional result was False
2025-09-25 00:14:35.179774 | 
2025-09-25 00:14:35.179924 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-25 00:14:35.609333 | controller -> localhost | changed
2025-09-25 00:14:35.634610 | 
2025-09-25 00:14:35.634771 | TASK [add-build-sshkey : Add back temp key]
2025-09-25 00:14:35.900151 | controller -> localhost | Identity added: /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/work/6443590069a542fcb4e934c80bcf51cb_id_rsa (zuul-build-sshkey)
2025-09-25 00:14:35.900495 | controller -> localhost | ok: Runtime: 0:00:00.012262
2025-09-25 00:14:35.915435 | 
2025-09-25 00:14:35.915613 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-25 00:14:36.381764 | controller | ok
2025-09-25 00:14:36.389098 | 
2025-09-25 00:14:36.389181 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-25 00:14:36.426497 | controller | skipping: Conditional result was False
2025-09-25 00:14:36.449247 | 
2025-09-25 00:14:36.449410 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-25 00:14:36.482460 | controller | ok
2025-09-25 00:14:36.506374 | 
2025-09-25 00:14:36.506515 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-25 00:14:36.756229 | controller -> localhost | ok
2025-09-25 00:14:36.765306 | 
2025-09-25 00:14:36.765398 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-25 00:14:36.798545 | controller | ok
2025-09-25 00:14:36.815425 | controller | included: /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-25 00:14:36.824799 | 
2025-09-25 00:14:36.824893 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-25 00:14:37.116949 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-25 00:14:37.117143 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/work/6443590069a542fcb4e934c80bcf51cb_id_ecdsa.
2025-09-25 00:14:37.117174 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/work/6443590069a542fcb4e934c80bcf51cb_id_ecdsa.pub.
2025-09-25 00:14:37.117204 | controller -> localhost | The key fingerprint is:
2025-09-25 00:14:37.117223 | controller -> localhost | SHA256:y+VoKNiy3bBBn8QWvm1Ofa33qX+QwllTTJx7X3ioJe4 zuul-build-sshkey
2025-09-25 00:14:37.117241 | controller -> localhost | The key's randomart image is:
2025-09-25 00:14:37.117260 | controller -> localhost | +---[ECDSA 521]---+
2025-09-25 00:14:37.117280 | controller -> localhost | |               +o|
2025-09-25 00:14:37.117299 | controller -> localhost | |               .+|
2025-09-25 00:14:37.117316 | controller -> localhost | |      .        +.|
2025-09-25 00:14:37.117333 | controller -> localhost | |     o .    . *.+|
2025-09-25 00:14:37.117351 | controller -> localhost | |    . = S .o * ++|
2025-09-25 00:14:37.117368 | controller -> localhost | |   + + * *  *.o .|
2025-09-25 00:14:37.117384 | controller -> localhost | |  o = = O o..... |
2025-09-25 00:14:37.117400 | controller -> localhost | |   + * =   .E.. o|
2025-09-25 00:14:37.117418 | controller -> localhost | |  . o . .   .oo+o|
2025-09-25 00:14:37.117436 | controller -> localhost | +----[SHA256]-----+
2025-09-25 00:14:37.117483 | controller -> localhost | ok: Runtime: 0:00:00.007713
2025-09-25 00:14:37.123943 | 
2025-09-25 00:14:37.124011 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-25 00:14:37.158758 | controller | ok
2025-09-25 00:14:37.175074 | controller | included: /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-25 00:14:37.189469 | 
2025-09-25 00:14:37.189588 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-25 00:14:37.215959 | controller | skipping: Conditional result was False
2025-09-25 00:14:37.225809 | 
2025-09-25 00:14:37.225902 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-25 00:14:37.712935 | controller | changed
2025-09-25 00:14:37.725746 | 
2025-09-25 00:14:37.725892 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-25 00:14:38.091632 | controller | ok
2025-09-25 00:14:38.103794 | 
2025-09-25 00:14:38.103923 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-25 00:14:39.411809 | controller | changed
2025-09-25 00:14:39.417334 | 
2025-09-25 00:14:39.417393 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-25 00:14:40.721194 | controller | changed
2025-09-25 00:14:40.729341 | 
2025-09-25 00:14:40.729539 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-25 00:14:40.757347 | controller | skipping: Conditional result was False
2025-09-25 00:14:40.772687 | 
2025-09-25 00:14:40.772843 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-25 00:14:41.086275 | controller -> localhost | changed
2025-09-25 00:14:41.097875 | 
2025-09-25 00:14:41.097954 | TASK [add-build-sshkey : Add back temp key]
2025-09-25 00:14:41.388043 | controller -> localhost | Identity added: /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/work/6443590069a542fcb4e934c80bcf51cb_id_ecdsa (zuul-build-sshkey)
2025-09-25 00:14:41.388430 | controller -> localhost | ok: Runtime: 0:00:00.013370
2025-09-25 00:14:41.402505 | 
2025-09-25 00:14:41.402639 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-25 00:14:41.749841 | controller | ok
2025-09-25 00:14:41.764331 | 
2025-09-25 00:14:41.764480 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-25 00:14:41.812410 | controller | skipping: Conditional result was False
2025-09-25 00:14:41.829091 | 
2025-09-25 00:14:41.829184 | TASK [include_role : remove-zuul-sshkey]
2025-09-25 00:14:41.854646 | controller | skipping: Conditional result was False
2025-09-25 00:14:41.863396 | 
2025-09-25 00:14:41.863480 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-25 00:14:42.205860 | controller | ok: "logs"
2025-09-25 00:14:42.206395 | controller | ok: All items complete
2025-09-25 00:14:42.206458 | 
2025-09-25 00:14:42.494974 | controller | ok: "artifacts"
2025-09-25 00:14:42.783966 | controller | ok: "docs"
2025-09-25 00:14:42.849006 | 
2025-09-25 00:14:42.849173 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-25 00:14:43.193266 | controller | changed: "logs"
2025-09-25 00:14:43.482858 | controller | changed: "artifacts"
2025-09-25 00:14:43.774780 | controller | changed: "docs"
2025-09-25 00:14:43.826791 | 
2025-09-25 00:14:43.826942 | PLAY RECAP
2025-09-25 00:14:43.827001 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-25 00:14:43.827063 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-25 00:14:43.827089 | 
2025-09-25 00:14:43.936234 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-25 00:14:43.937098 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-25 00:14:44.566832 | 
2025-09-25 00:14:44.566943 | PLAY [all]
2025-09-25 00:14:44.591427 | 
2025-09-25 00:14:44.591545 | TASK [Install binary dependencies]
2025-09-25 00:14:44.652197 | controller | ok
2025-09-25 00:14:44.671223 | 
2025-09-25 00:14:44.671332 | TASK [bindep : Include find tasks]
2025-09-25 00:14:44.712852 | controller | ok
2025-09-25 00:14:44.723551 | controller | included: /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-25 00:14:44.731919 | 
2025-09-25 00:14:44.732005 | TASK [bindep : Look for bindep.txt]
2025-09-25 00:14:45.261884 | controller | ok
2025-09-25 00:14:45.277410 | 
2025-09-25 00:14:45.277636 | TASK [bindep : Define bindep_file fact]
2025-09-25 00:14:45.298504 | controller | skipping: Conditional result was False
2025-09-25 00:14:45.318659 | 
2025-09-25 00:14:45.318867 | TASK [bindep : Look for other-requirements.txt]
2025-09-25 00:14:45.640327 | controller | ok
2025-09-25 00:14:45.647663 | 
2025-09-25 00:14:45.647755 | TASK [bindep : Define bindep_file fact]
2025-09-25 00:14:45.683228 | controller | skipping: Conditional result was False
2025-09-25 00:14:45.691580 | 
2025-09-25 00:14:45.691675 | TASK [bindep : Look for bindep fallback file]
2025-09-25 00:14:45.728215 | controller | skipping: Conditional result was False
2025-09-25 00:14:45.737276 | 
2025-09-25 00:14:45.737376 | TASK [bindep : Define bindep_file fact]
2025-09-25 00:14:45.773155 | controller | skipping: Conditional result was False
2025-09-25 00:14:45.786520 | 
2025-09-25 00:14:45.786785 | TASK [bindep : Include bindep tasks]
2025-09-25 00:14:45.824672 | controller | skipping: Conditional result was False
2025-09-25 00:14:45.841908 | 
2025-09-25 00:14:45.842098 | TASK [bindep : Include install tasks]
2025-09-25 00:14:45.880355 | controller | skipping: Conditional result was False
2025-09-25 00:14:45.895317 | 
2025-09-25 00:14:45.895489 | LOOP [bindep : Include package tasks]
2025-09-25 00:14:45.999358 | 
2025-09-25 00:14:45.999763 | TASK [Run test-setup role]
2025-09-25 00:14:46.031107 | controller | ok
2025-09-25 00:14:46.055762 | 
2025-09-25 00:14:46.056150 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-25 00:14:46.392122 | controller | ok
2025-09-25 00:14:46.405331 | 
2025-09-25 00:14:46.405465 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-25 00:14:46.553696 | controller | skipping: Conditional result was False
2025-09-25 00:14:46.592577 | 
2025-09-25 00:14:46.592690 | PLAY RECAP
2025-09-25 00:14:46.592743 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-25 00:14:46.592772 | 
2025-09-25 00:14:46.693198 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-25 00:14:46.694107 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-25 00:14:47.347106 | 
2025-09-25 00:14:47.347288 | PLAY [controller]
2025-09-25 00:14:47.366989 | 
2025-09-25 00:14:47.367137 | TASK [Create the /root directory]
2025-09-25 00:14:48.110923 | controller | ok
2025-09-25 00:14:48.116809 | 
2025-09-25 00:14:48.116882 | TASK [Install glibc-langpack-en]
2025-09-25 00:14:56.100029 | controller | ok: Nothing to do
2025-09-25 00:14:56.107250 | 
2025-09-25 00:14:56.107327 | TASK [Ensure controller directory exists]
2025-09-25 00:14:56.629804 | controller | changed
2025-09-25 00:14:56.641156 | 
2025-09-25 00:14:56.641306 | TASK [Install container runtime]
2025-09-25 00:14:56.696744 | controller | ok
2025-09-25 00:14:56.747532 | 
2025-09-25 00:14:56.747683 | LOOP [ensure-podman : Find distribution installation]
2025-09-25 00:14:56.781424 | controller | ok: "/var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-25 00:14:56.789208 | controller | included: /var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-25 00:14:56.795557 | 
2025-09-25 00:14:56.795631 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-25 00:16:14.763755 | controller | changed
2025-09-25 00:16:14.778977 | 
2025-09-25 00:16:14.779166 | TASK [ensure-podman : Fetch podman version]
2025-09-25 00:16:15.597313 | controller | Client:       Podman Engine
2025-09-25 00:16:15.638089 | controller | Version:      4.6.2
2025-09-25 00:16:15.638135 | controller | API Version:  4.6.2
2025-09-25 00:16:15.638142 | controller | Go Version:   go1.19.12
2025-09-25 00:16:15.638159 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-25 00:16:15.638167 | controller | OS/Arch:      linux/amd64
2025-09-25 00:16:15.930631 | controller | ok: Runtime: 0:00:00.231223
2025-09-25 00:16:15.943739 | 
2025-09-25 00:16:15.943890 | TASK [ensure-podman : Print podman version installed]
2025-09-25 00:16:15.983407 | Podman version: Client:       Podman Engine
2025-09-25 00:16:15.983568 | Version:      4.6.2
2025-09-25 00:16:15.983597 | API Version:  4.6.2
2025-09-25 00:16:15.983618 | Go Version:   go1.19.12
2025-09-25 00:16:15.983636 | Built:        Mon Aug 28 19:38:31 2023
2025-09-25 00:16:15.983655 | OS/Arch:      linux/amd64
2025-09-25 00:16:15.989363 | 
2025-09-25 00:16:15.989435 | TASK [ensure-podman : Validate podman engine]
2025-09-25 00:16:16.119802 | controller | skipping: Conditional result was False
2025-09-25 00:16:16.132699 | 
2025-09-25 00:16:16.132853 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-25 00:16:16.169779 | controller | skipping: Conditional result was False
2025-09-25 00:16:16.194239 | 
2025-09-25 00:16:16.194421 | TASK [Ensure python3.8 is present]
2025-09-25 00:16:16.221936 | controller | skipping: Conditional result was False
2025-09-25 00:16:16.233727 | 
2025-09-25 00:16:16.233883 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-25 00:16:16.259192 | controller | ok
2025-09-25 00:16:16.285899 | 
2025-09-25 00:16:16.286054 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-25 00:16:20.208715 | controller | ok: Nothing to do
2025-09-25 00:16:20.217416 | 
2025-09-25 00:16:20.217533 | TASK [our-ensure-python : Also install python3-devel]
2025-09-25 00:16:33.125381 | controller | changed
2025-09-25 00:16:33.141416 | 
2025-09-25 00:16:33.141520 | TASK [Run ensure-virtualenv role]
2025-09-25 00:16:33.160789 | controller | ok
2025-09-25 00:16:33.182567 | 
2025-09-25 00:16:33.182703 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-25 00:16:33.574515 | controller | /usr/bin/virtualenv
2025-09-25 00:16:33.847575 | controller | ok: Runtime: 0:00:00.005049
2025-09-25 00:16:33.853556 | 
2025-09-25 00:16:33.853652 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-25 00:16:33.903030 | controller | skipping: Conditional result was False
2025-09-25 00:16:33.903319 | controller | ok: All items complete
2025-09-25 00:16:33.903347 | 
2025-09-25 00:16:33.927068 | 
2025-09-25 00:16:33.927195 | TASK [Find the full path of the Python interpreter]
2025-09-25 00:16:34.261266 | controller | /usr/bin/python3
2025-09-25 00:16:34.587488 | controller | ok
2025-09-25 00:16:34.594008 | 
2025-09-25 00:16:34.594148 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-25 00:16:36.063878 | controller | created virtual environment CPython3.11.0.final.0-64 in 764ms
2025-09-25 00:16:36.114601 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-25 00:16:36.114660 | 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-09-25 00:16:36.114680 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-25 00:16:36.114702 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-25 00:16:36.237410 | controller | changed
2025-09-25 00:16:36.243527 | 
2025-09-25 00:16:36.243595 | TASK [Set selinux package]
2025-09-25 00:16:36.273213 | controller | ok
2025-09-25 00:16:36.280454 | 
2025-09-25 00:16:36.280660 | TASK [Set selinux package (Fedora)]
2025-09-25 00:16:36.318989 | controller | ok
2025-09-25 00:16:36.330256 | 
2025-09-25 00:16:36.330387 | TASK [Install selinux into virtualenv]
2025-09-25 00:16:38.985127 | controller | Collecting selinux-please-lie-to-me
2025-09-25 00:16:39.079256 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-25 00:16:39.611133 | controller | Collecting setuptools<50.0.0
2025-09-25 00:16:39.626084 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-25 00:16:39.766064 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.1 MB/s eta 0:00:00
2025-09-25 00:16:39.921969 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-25 00:16:39.922277 | controller |   Attempting uninstall: setuptools
2025-09-25 00:16:39.927171 | controller |     Found existing installation: setuptools 62.6.0
2025-09-25 00:16:40.040256 | controller |     Uninstalling setuptools-62.6.0:
2025-09-25 00:16:40.055756 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-25 00:16:40.789890 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-25 00:16:41.003767 | controller |
2025-09-25 00:16:41.219307 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-25 00:16:41.219354 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-25 00:16:41.509269 | controller | ok: Runtime: 0:00:04.408113
2025-09-25 00:16:41.523431 | 
2025-09-25 00:16:41.523767 | TASK [Install pytest-forked into virtualenv]
2025-09-25 00:16:42.763555 | controller | Collecting pytest-forked
2025-09-25 00:16:42.853170 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-25 00:16:42.914291 | controller | Collecting py
2025-09-25 00:16:42.927773 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-25 00:16:42.965830 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00
2025-09-25 00:16:43.140898 | controller | Collecting pytest>=3.10
2025-09-25 00:16:43.154468 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-25 00:16:43.219565 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.9 MB/s eta 0:00:00
2025-09-25 00:16:43.276558 | controller | Collecting iniconfig>=1
2025-09-25 00:16:43.290151 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-25 00:16:43.358417 | controller | Collecting packaging>=20
2025-09-25 00:16:43.372029 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-25 00:16:43.384145 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.9 MB/s eta 0:00:00
2025-09-25 00:16:43.430970 | controller | Collecting pluggy<2,>=1.5
2025-09-25 00:16:43.444322 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-25 00:16:43.507030 | controller | Collecting pygments>=2.7.2
2025-09-25 00:16:43.519897 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-25 00:16:43.652268 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.5 MB/s eta 0:00:00
2025-09-25 00:16:43.782088 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-25 00:16:46.100109 | controller | Successfully installed iniconfig-2.1.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-09-25 00:16:46.116361 | controller |
2025-09-25 00:16:46.306559 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-25 00:16:46.306611 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-25 00:16:46.695702 | controller | ok: Runtime: 0:00:04.282677
2025-09-25 00:16:46.701455 | 
2025-09-25 00:16:46.701516 | TASK [Update pip]
2025-09-25 00:16:47.806799 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-25 00:16:48.088020 | controller | Collecting pip
2025-09-25 00:16:48.192431 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-25 00:16:48.363918 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.7 MB/s eta 0:00:00
2025-09-25 00:16:48.508176 | controller | Installing collected packages: pip
2025-09-25 00:16:48.508624 | controller |   Attempting uninstall: pip
2025-09-25 00:16:48.513131 | controller |     Found existing installation: pip 22.2.2
2025-09-25 00:16:48.774523 | controller |     Uninstalling pip-22.2.2:
2025-09-25 00:16:48.804699 | controller |       Successfully uninstalled pip-22.2.2
2025-09-25 00:16:50.556088 | controller | Successfully installed pip-25.2
2025-09-25 00:16:50.843459 | controller | ok: Runtime: 0:00:03.542507
2025-09-25 00:16:50.852145 | 
2025-09-25 00:16:50.852285 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-25 00:16:51.382663 | controller | changed
2025-09-25 00:16:51.394809 | 
2025-09-25 00:16:51.394943 | TASK [Install ansible into virtualenv]
2025-09-25 00:16:52.474541 | controller | Processing ./src/github.com/ansible/ansible
2025-09-25 00:16:52.481009 | controller |   Installing build dependencies: started
2025-09-25 00:16:54.354601 | controller |   Installing build dependencies: finished with status 'done'
2025-09-25 00:16:54.355737 | controller |   Getting requirements to build wheel: started
2025-09-25 00:16:55.907544 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-25 00:16:55.908975 | controller |   Preparing metadata (pyproject.toml): started
2025-09-25 00:16:56.842506 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-25 00:16:56.847630 | 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-09-25 00:16:56.852512 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-25 00:16:57.072458 | controller | ERROR
2025-09-25 00:16:57.072644 | controller | {
2025-09-25 00:16:57.072681 | controller |   "delta": "0:00:05.153103",
2025-09-25 00:16:57.072707 | controller |   "end": "2025-09-25 00:16:57.001647",
2025-09-25 00:16:57.072730 | controller |   "msg": "non-zero return code",
2025-09-25 00:16:57.072764 | controller |   "rc": 1,
2025-09-25 00:16:57.072787 | controller |   "start": "2025-09-25 00:16:51.848544"
2025-09-25 00:16:57.072809 | controller | }
failure
2025-09-25 00:16:57.074570 | 
2025-09-25 00:16:57.074626 | PLAY RECAP
2025-09-25 00:16:57.074677 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-25 00:16:57.074706 | 
2025-09-25 00:16:57.176840 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-25 00:16:57.178753 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-25 00:16:57.788313 | 
2025-09-25 00:16:57.788433 | PLAY [all]
2025-09-25 00:16:57.809660 | 
2025-09-25 00:16:57.809764 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-25 00:16:58.624413 | controller | changed: non-zero return code
2025-09-25 00:16:58.636882 | 
2025-09-25 00:16:58.637128 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-25 00:16:58.665069 | controller | skipping: Conditional result was False
2025-09-25 00:16:58.677978 | 
2025-09-25 00:16:58.678188 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-25 00:16:58.720341 | 
2025-09-25 00:16:58.720649 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-25 00:16:58.762082 | 
2025-09-25 00:16:58.762527 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-25 00:16:58.789497 | controller | skipping: Conditional result was False
2025-09-25 00:16:58.805589 | 
2025-09-25 00:16:58.805812 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-25 00:16:58.849133 | 
2025-09-25 00:16:58.849421 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-25 00:16:58.876509 | controller | skipping: Conditional result was False
2025-09-25 00:16:58.890182 | 
2025-09-25 00:16:58.890333 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-25 00:16:58.916862 | controller | skipping: Conditional result was False
2025-09-25 00:16:58.925568 | 
2025-09-25 00:16:58.925703 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-25 00:16:58.951229 | controller | skipping: Conditional result was False
2025-09-25 00:16:58.997068 | 
2025-09-25 00:16:58.997177 | PLAY RECAP
2025-09-25 00:16:58.997233 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-25 00:16:58.997263 | 
2025-09-25 00:16:59.091109 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-25 00:16:59.091941 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-25 00:16:59.651945 | 
2025-09-25 00:16:59.652134 | PLAY [all:!appliance*]
2025-09-25 00:16:59.673345 | 
2025-09-25 00:16:59.673465 | TASK [unregister the node]
2025-09-25 00:16:59.804845 | controller | skipping: Conditional result was False
2025-09-25 00:16:59.817333 | 
2025-09-25 00:16:59.817494 | TASK [include_role : fetch-output]
2025-09-25 00:16:59.866122 | controller | ok
2025-09-25 00:16:59.902207 | 
2025-09-25 00:16:59.902302 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-25 00:16:59.958350 | controller | skipping: Conditional result was False
2025-09-25 00:16:59.970083 | 
2025-09-25 00:16:59.970249 | TASK [fetch-output : Set log path for single node]
2025-09-25 00:17:00.030664 | controller | ok
2025-09-25 00:17:00.041856 | 
2025-09-25 00:17:00.041988 | LOOP [fetch-output : Ensure local output dirs]
2025-09-25 00:17:00.477906 | controller -> localhost | ok: "/var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/work/logs"
2025-09-25 00:17:00.751901 | controller -> localhost | changed: "/var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/work/artifacts"
2025-09-25 00:17:00.965196 | controller -> localhost | changed: "/var/lib/zuul/builds/6443590069a542fcb4e934c80bcf51cb/work/docs"
2025-09-25 00:17:00.981051 | 
2025-09-25 00:17:00.981182 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-25 00:17:02.146809 | controller | changed:
2025-09-25 00:17:02.147303 | controller | .d..t...... ./
2025-09-25 00:17:02.147375 | controller | cd+++++++++ controller/
2025-09-25 00:17:02.147454 | controller | changed: All items complete
2025-09-25 00:17:02.147504 | 
2025-09-25 00:17:03.234693 | controller | changed: .d..t...... ./
2025-09-25 00:17:04.314702 | controller | changed: .d..t...... ./
2025-09-25 00:17:04.348978 | 
2025-09-25 00:17:04.349218 | TASK [include_role : fetch-output-openshift]
2025-09-25 00:17:04.376645 | controller | skipping: Conditional result was False
2025-09-25 00:17:04.391558 | 
2025-09-25 00:17:04.391747 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-25 00:17:04.423612 | controller | skipping: Conditional result was False
2025-09-25 00:17:04.434649 | controller | skipping: Conditional result was False
2025-09-25 00:17:04.476303 | 
2025-09-25 00:17:04.476429 | PLAY [localhost]
2025-09-25 00:17:04.494271 | 
2025-09-25 00:17:04.494387 | TASK [Run Zuul manifest role]
2025-09-25 00:17:04.512151 | localhost | ok
2025-09-25 00:17:04.525601 | 
2025-09-25 00:17:04.525699 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-25 00:17:04.886081 | localhost | changed
2025-09-25 00:17:04.896300 | 
2025-09-25 00:17:04.896439 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-25 00:17:04.933496 | localhost | ok
2025-09-25 00:17:04.951974 | 
2025-09-25 00:17:04.952144 | TASK [Set zuul-log-path fact]
2025-09-25 00:17:04.974739 | localhost | ok
2025-09-25 00:17:04.993777 | 
2025-09-25 00:17:04.993904 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-25 00:17:05.038272 | localhost | ok
2025-09-25 00:17:05.056838 | 
2025-09-25 00:17:05.056964 | LOOP [Run upload-logs-swift role]
2025-09-25 00:17:05.105809 | localhost | Output suppressed because no_log was given
2025-09-25 00:17:05.152544 | 
2025-09-25 00:17:05.152689 | TASK [Set zuul-log-path fact]
2025-09-25 00:17:05.189741 | localhost | skipping: Conditional result was False
2025-09-25 00:17:05.197678 | 
2025-09-25 00:17:05.197776 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-25 00:17:05.650345 | localhost -> localhost | ok: Runtime: 0:00:00.006877
2025-09-25 00:17:05.655548 | 
2025-09-25 00:17:05.655637 | TASK [upload-logs-swift : Upload logs to swift]