2025-09-17 00:11:54.529555 | Job console starting...
2025-09-17 00:11:54.539512 | Updating repositories
2025-09-17 00:11:54.678434 | Preparing job workspace
2025-09-17 00:11:58.082263 | Running Ansible setup...
2025-09-17 00:12:05.216701 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-17 00:12:05.823511 | 
2025-09-17 00:12:05.823628 | PLAY [localhost]
2025-09-17 00:12:05.831865 | 
2025-09-17 00:12:05.831933 | TASK [Gathering Facts]
2025-09-17 00:12:06.901393 | localhost | ok
2025-09-17 00:12:06.917681 | 
2025-09-17 00:12:06.917776 | TASK [Setup log path fact]
2025-09-17 00:12:06.938944 | localhost | ok
2025-09-17 00:12:06.955337 | 
2025-09-17 00:12:06.955425 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-17 00:12:06.995889 | localhost | ok
2025-09-17 00:12:07.005937 | 
2025-09-17 00:12:07.006014 | TASK [emit-job-header : Print job information]
2025-09-17 00:12:07.036364 | # Job Information
2025-09-17 00:12:07.036489 | Ansible Version: 2.15.12
2025-09-17 00:12:07.036520 | Job: ansible-test-sanity-docker-devel
2025-09-17 00:12:07.036541 | Pipeline: periodic
2025-09-17 00:12:07.036560 | Executor: ze02.softwarefactory-project.io
2025-09-17 00:12:07.036577 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-17 00:12:07.036599 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/be2/ansible/be2d6962ab6444559051d28f86ddf116/
2025-09-17 00:12:07.036618 | Event ID: eca5199f70dd4f21ae7c1e30717f8aa4
2025-09-17 00:12:07.041360 | 
2025-09-17 00:12:07.041443 | LOOP [emit-job-header : Print node information]
2025-09-17 00:12:07.137806 | localhost | ok:
2025-09-17 00:12:07.138088 | localhost | # Node Information
2025-09-17 00:12:07.138150 | localhost | Inventory Hostname: controller
2025-09-17 00:12:07.138197 | localhost | Hostname: ip-172-16-113-37
2025-09-17 00:12:07.138242 | localhost | Username: zuul-worker
2025-09-17 00:12:07.138315 | localhost | Distro: Fedora 37
2025-09-17 00:12:07.138363 | localhost | Provider: ansible-us-east-2
2025-09-17 00:12:07.138405 | localhost | Region: us-east-2
2025-09-17 00:12:07.138446 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-17 00:12:07.138486 | localhost | Product Name: t3.small
2025-09-17 00:12:07.138526 | localhost | Interface IP: 18.191.151.251
2025-09-17 00:12:07.149819 | 
2025-09-17 00:12:07.149966 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-17 00:12:07.562324 | localhost -> localhost | changed
2025-09-17 00:12:07.574329 | 
2025-09-17 00:12:07.574475 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-17 00:12:08.552622 | localhost -> localhost | changed
2025-09-17 00:12:08.596481 | 
2025-09-17 00:12:08.596613 | PLAY [all:!appliance*]
2025-09-17 00:12:08.628955 | 
2025-09-17 00:12:08.629069 | TASK [include_role : start-zuul-console]
2025-09-17 00:12:08.652338 | controller | ok
2025-09-17 00:12:08.671643 | 
2025-09-17 00:12:08.671772 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-17 00:12:09.349272 | controller | ok
2025-09-17 00:12:09.372194 | 
2025-09-17 00:12:09.372344 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-17 00:12:10.992692 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-17 00:12:11.005703 | 
2025-09-17 00:12:11.005846 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-17 00:12:11.153437 | controller | skipping: Conditional result was False
2025-09-17 00:12:11.166635 | 
2025-09-17 00:12:11.166856 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-17 00:12:11.194541 | controller | skipping: Conditional result was False
2025-09-17 00:12:11.203517 | 
2025-09-17 00:12:11.203608 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-17 00:12:11.229008 | controller | skipping: Conditional result was False
2025-09-17 00:12:11.237598 | 
2025-09-17 00:12:11.237707 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-17 00:12:11.263329 | controller | skipping: Conditional result was False
2025-09-17 00:12:11.272072 | 
2025-09-17 00:12:11.272180 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-17 00:12:11.297919 | controller | skipping: Conditional result was False
2025-09-17 00:12:11.306033 | 
2025-09-17 00:12:11.306123 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-17 00:12:11.331071 | controller | skipping: Conditional result was False
2025-09-17 00:12:11.346567 | 
2025-09-17 00:12:11.346657 | TASK [Disable Fedora Modular]
2025-09-17 00:12:12.076723 | controller | changed
2025-09-17 00:12:12.089042 | 
2025-09-17 00:12:12.089341 | TASK [Enable EPEL]
2025-09-17 00:12:12.116883 | controller | skipping: Conditional result was False
2025-09-17 00:12:12.129582 | 
2025-09-17 00:12:12.129753 | TASK [Register the RHEL node]
2025-09-17 00:12:12.278186 | 
2025-09-17 00:12:12.278378 | TASK [Show the subscription-manager status]
2025-09-17 00:12:12.447290 | controller | skipping: Conditional result was False
2025-09-17 00:12:12.461441 | 
2025-09-17 00:12:12.461584 | TASK [Enable EPEL on RHEL]
2025-09-17 00:12:12.621032 | controller | skipping: Conditional result was False
2025-09-17 00:12:12.636787 | 
2025-09-17 00:12:12.636966 | TASK [Install git and tox]
2025-09-17 00:13:43.303212 | controller | changed
2025-09-17 00:13:43.310179 | 
2025-09-17 00:13:43.310252 | TASK [include_role : prepare-workspace]
2025-09-17 00:13:43.354151 | controller | ok
2025-09-17 00:13:43.383907 | 
2025-09-17 00:13:43.384073 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-17 00:13:43.897829 | controller | ok
2025-09-17 00:13:43.906105 | 
2025-09-17 00:13:43.906173 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-17 00:13:56.266485 | controller | Output suppressed because no_log was given
2025-09-17 00:13:56.275900 | 
2025-09-17 00:13:56.275962 | TASK [include_role : prepare-workspace-openshift]
2025-09-17 00:13:56.302528 | controller | skipping: Conditional result was False
2025-09-17 00:13:56.323247 | 
2025-09-17 00:13:56.323337 | PLAY [all:!appliance]
2025-09-17 00:13:56.339075 | 
2025-09-17 00:13:56.339167 | TASK [Run add-build-sshkey role (RSA)]
2025-09-17 00:13:56.368579 | controller | ok
2025-09-17 00:13:56.382312 | 
2025-09-17 00:13:56.382390 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-17 00:13:56.611050 | controller -> localhost | ok
2025-09-17 00:13:56.644044 | 
2025-09-17 00:13:56.644154 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-17 00:13:56.673845 | controller | ok
2025-09-17 00:13:56.687211 | controller | included: /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-17 00:13:56.692745 | 
2025-09-17 00:13:56.692804 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-17 00:13:57.094712 | controller -> localhost | Generating public/private rsa key pair.
2025-09-17 00:13:57.094923 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/work/be2d6962ab6444559051d28f86ddf116_id_rsa.
2025-09-17 00:13:57.094957 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/work/be2d6962ab6444559051d28f86ddf116_id_rsa.pub.
2025-09-17 00:13:57.094980 | controller -> localhost | The key fingerprint is:
2025-09-17 00:13:57.095000 | controller -> localhost | SHA256:kbaQisgKOy5KwqL2BIFTuQQVROOHbATHhArvo3/mnoM zuul-build-sshkey
2025-09-17 00:13:57.095019 | controller -> localhost | The key's randomart image is:
2025-09-17 00:13:57.095039 | controller -> localhost | +---[RSA 2048]----+
2025-09-17 00:13:57.095058 | controller -> localhost | |oX@o             |
2025-09-17 00:13:57.095077 | controller -> localhost | |+*+o   . .       |
2025-09-17 00:13:57.095096 | controller -> localhost | |=+=.. o +        |
2025-09-17 00:13:57.095113 | controller -> localhost | |o++o . o o       |
2025-09-17 00:13:57.095131 | controller -> localhost | |o+. .   S        |
2025-09-17 00:13:57.095158 | controller -> localhost | |+.+              |
2025-09-17 00:13:57.095180 | controller -> localhost | |*+ +             |
2025-09-17 00:13:57.095199 | controller -> localhost | |OoE +.           |
2025-09-17 00:13:57.095218 | controller -> localhost | |*oo*+.           |
2025-09-17 00:13:57.095238 | controller -> localhost | +----[SHA256]-----+
2025-09-17 00:13:57.095283 | controller -> localhost | ok: Runtime: 0:00:00.050627
2025-09-17 00:13:57.102372 | 
2025-09-17 00:13:57.102459 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-17 00:13:57.133271 | controller | ok
2025-09-17 00:13:57.143016 | controller | included: /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-17 00:13:57.151854 | 
2025-09-17 00:13:57.151935 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-17 00:13:57.176458 | controller | skipping: Conditional result was False
2025-09-17 00:13:57.182608 | 
2025-09-17 00:13:57.182673 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-17 00:13:57.788099 | controller | changed
2025-09-17 00:13:57.807247 | 
2025-09-17 00:13:57.807354 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-17 00:13:58.182568 | controller | ok
2025-09-17 00:13:58.191623 | 
2025-09-17 00:13:58.191816 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-17 00:13:59.462393 | controller | changed
2025-09-17 00:13:59.474103 | 
2025-09-17 00:13:59.474517 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-17 00:14:00.817952 | controller | changed
2025-09-17 00:14:00.823543 | 
2025-09-17 00:14:00.823624 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-17 00:14:00.848610 | controller | skipping: Conditional result was False
2025-09-17 00:14:00.856406 | 
2025-09-17 00:14:00.856488 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-17 00:14:01.242471 | controller -> localhost | changed
2025-09-17 00:14:01.272538 | 
2025-09-17 00:14:01.272748 | TASK [add-build-sshkey : Add back temp key]
2025-09-17 00:14:01.619268 | controller -> localhost | Identity added: /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/work/be2d6962ab6444559051d28f86ddf116_id_rsa (zuul-build-sshkey)
2025-09-17 00:14:01.619569 | controller -> localhost | ok: Runtime: 0:00:00.013546
2025-09-17 00:14:01.630953 | 
2025-09-17 00:14:01.631059 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-17 00:14:02.715126 | controller | ok
2025-09-17 00:14:02.726811 | 
2025-09-17 00:14:02.726948 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-17 00:14:02.764046 | controller | skipping: Conditional result was False
2025-09-17 00:14:02.789429 | 
2025-09-17 00:14:02.789589 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-17 00:14:02.827519 | controller | ok
2025-09-17 00:14:02.857471 | 
2025-09-17 00:14:02.857582 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-17 00:14:03.125688 | controller -> localhost | ok
2025-09-17 00:14:03.132070 | 
2025-09-17 00:14:03.132137 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-17 00:14:03.161272 | controller | ok
2025-09-17 00:14:03.173443 | controller | included: /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-17 00:14:03.179063 | 
2025-09-17 00:14:03.179125 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-17 00:14:03.466377 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-17 00:14:03.466579 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/work/be2d6962ab6444559051d28f86ddf116_id_ecdsa.
2025-09-17 00:14:03.466608 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/work/be2d6962ab6444559051d28f86ddf116_id_ecdsa.pub.
2025-09-17 00:14:03.466635 | controller -> localhost | The key fingerprint is:
2025-09-17 00:14:03.466655 | controller -> localhost | SHA256:uFxlrFZdvOTPntWEpu7TlKujcBJrmTG4RjwAbEcqH7k zuul-build-sshkey
2025-09-17 00:14:03.466701 | controller -> localhost | The key's randomart image is:
2025-09-17 00:14:03.466723 | controller -> localhost | +---[ECDSA 521]---+
2025-09-17 00:14:03.466742 | controller -> localhost | | ....        ..  |
2025-09-17 00:14:03.466760 | controller -> localhost | |  o+.    . . .o  |
2025-09-17 00:14:03.466777 | controller -> localhost | |..+..     = .o o |
2025-09-17 00:14:03.466794 | controller -> localhost | | o o o o =    = .|
2025-09-17 00:14:03.466811 | controller -> localhost | |  E   * S    o =.|
2025-09-17 00:14:03.466828 | controller -> localhost | |     o * B  . o =|
2025-09-17 00:14:03.466845 | controller -> localhost | |      = B .. o oo|
2025-09-17 00:14:03.466863 | controller -> localhost | |     . . +  + o..|
2025-09-17 00:14:03.466879 | controller -> localhost | |          .oo+   |
2025-09-17 00:14:03.466897 | controller -> localhost | +----[SHA256]-----+
2025-09-17 00:14:03.466939 | controller -> localhost | ok: Runtime: 0:00:00.013828
2025-09-17 00:14:03.473790 | 
2025-09-17 00:14:03.473852 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-17 00:14:03.503644 | controller | ok
2025-09-17 00:14:03.510790 | controller | included: /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-17 00:14:03.518982 | 
2025-09-17 00:14:03.519040 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-17 00:14:03.542520 | controller | skipping: Conditional result was False
2025-09-17 00:14:03.549748 | 
2025-09-17 00:14:03.549810 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-17 00:14:04.495299 | controller | changed
2025-09-17 00:14:04.507291 | 
2025-09-17 00:14:04.507427 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-17 00:14:05.140091 | controller | ok
2025-09-17 00:14:05.155051 | 
2025-09-17 00:14:05.155192 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-17 00:14:06.504627 | controller | changed
2025-09-17 00:14:06.517553 | 
2025-09-17 00:14:06.517722 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-17 00:14:07.830790 | controller | changed
2025-09-17 00:14:07.843129 | 
2025-09-17 00:14:07.843263 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-17 00:14:07.880843 | controller | skipping: Conditional result was False
2025-09-17 00:14:07.894157 | 
2025-09-17 00:14:07.894301 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-17 00:14:08.218205 | controller -> localhost | changed
2025-09-17 00:14:08.242842 | 
2025-09-17 00:14:08.242986 | TASK [add-build-sshkey : Add back temp key]
2025-09-17 00:14:08.617224 | controller -> localhost | Identity added: /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/work/be2d6962ab6444559051d28f86ddf116_id_ecdsa (zuul-build-sshkey)
2025-09-17 00:14:08.617711 | controller -> localhost | ok: Runtime: 0:00:00.014727
2025-09-17 00:14:08.634747 | 
2025-09-17 00:14:08.634887 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-17 00:14:09.024866 | controller | ok
2025-09-17 00:14:09.038086 | 
2025-09-17 00:14:09.038365 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-17 00:14:09.077538 | controller | skipping: Conditional result was False
2025-09-17 00:14:09.106394 | 
2025-09-17 00:14:09.106599 | TASK [include_role : remove-zuul-sshkey]
2025-09-17 00:14:09.125309 | controller | skipping: Conditional result was False
2025-09-17 00:14:09.134311 | 
2025-09-17 00:14:09.134403 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-17 00:14:09.537254 | controller | ok: "logs"
2025-09-17 00:14:09.537599 | controller | ok: All items complete
2025-09-17 00:14:09.537642 | 
2025-09-17 00:14:09.796776 | controller | ok: "artifacts"
2025-09-17 00:14:10.097806 | controller | ok: "docs"
2025-09-17 00:14:10.110739 | 
2025-09-17 00:14:10.110826 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-17 00:14:10.461650 | controller | changed: "logs"
2025-09-17 00:14:10.769308 | controller | changed: "artifacts"
2025-09-17 00:14:11.084296 | controller | changed: "docs"
2025-09-17 00:14:11.150976 | 
2025-09-17 00:14:11.151082 | PLAY RECAP
2025-09-17 00:14:11.151154 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-17 00:14:11.151194 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-17 00:14:11.151222 | 
2025-09-17 00:14:11.270224 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-17 00:14:11.271961 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-17 00:14:11.904559 | 
2025-09-17 00:14:11.904711 | PLAY [all]
2025-09-17 00:14:11.926480 | 
2025-09-17 00:14:11.926599 | TASK [Install binary dependencies]
2025-09-17 00:14:11.976614 | controller | ok
2025-09-17 00:14:11.996710 | 
2025-09-17 00:14:11.996826 | TASK [bindep : Include find tasks]
2025-09-17 00:14:12.046483 | controller | ok
2025-09-17 00:14:12.054140 | controller | included: /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-17 00:14:12.060043 | 
2025-09-17 00:14:12.060107 | TASK [bindep : Look for bindep.txt]
2025-09-17 00:14:12.574066 | controller | ok
2025-09-17 00:14:12.587126 | 
2025-09-17 00:14:12.587272 | TASK [bindep : Define bindep_file fact]
2025-09-17 00:14:12.614397 | controller | skipping: Conditional result was False
2025-09-17 00:14:12.626582 | 
2025-09-17 00:14:12.626759 | TASK [bindep : Look for other-requirements.txt]
2025-09-17 00:14:12.969303 | controller | ok
2025-09-17 00:14:12.980992 | 
2025-09-17 00:14:12.981138 | TASK [bindep : Define bindep_file fact]
2025-09-17 00:14:13.018281 | controller | skipping: Conditional result was False
2025-09-17 00:14:13.030606 | 
2025-09-17 00:14:13.030795 | TASK [bindep : Look for bindep fallback file]
2025-09-17 00:14:13.067968 | controller | skipping: Conditional result was False
2025-09-17 00:14:13.080830 | 
2025-09-17 00:14:13.080980 | TASK [bindep : Define bindep_file fact]
2025-09-17 00:14:13.117877 | controller | skipping: Conditional result was False
2025-09-17 00:14:13.130109 | 
2025-09-17 00:14:13.130248 | TASK [bindep : Include bindep tasks]
2025-09-17 00:14:13.167136 | controller | skipping: Conditional result was False
2025-09-17 00:14:13.183998 | 
2025-09-17 00:14:13.184165 | TASK [bindep : Include install tasks]
2025-09-17 00:14:13.211180 | controller | skipping: Conditional result was False
2025-09-17 00:14:13.224392 | 
2025-09-17 00:14:13.224543 | LOOP [bindep : Include package tasks]
2025-09-17 00:14:13.298507 | 
2025-09-17 00:14:13.298879 | TASK [Run test-setup role]
2025-09-17 00:14:13.325495 | controller | ok
2025-09-17 00:14:13.362007 | 
2025-09-17 00:14:13.362100 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-17 00:14:13.723964 | controller | ok
2025-09-17 00:14:13.736512 | 
2025-09-17 00:14:13.736643 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-17 00:14:13.884289 | controller | skipping: Conditional result was False
2025-09-17 00:14:13.916532 | 
2025-09-17 00:14:13.916605 | PLAY RECAP
2025-09-17 00:14:13.916656 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-17 00:14:13.916708 | 
2025-09-17 00:14:14.011917 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-17 00:14:14.012790 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-17 00:14:14.617374 | 
2025-09-17 00:14:14.617549 | PLAY [controller]
2025-09-17 00:14:14.636750 | 
2025-09-17 00:14:14.636831 | TASK [Create the /root directory]
2025-09-17 00:14:15.377486 | controller | ok
2025-09-17 00:14:15.390323 | 
2025-09-17 00:14:15.390482 | TASK [Install glibc-langpack-en]
2025-09-17 00:14:23.497344 | controller | ok: Nothing to do
2025-09-17 00:14:23.509148 | 
2025-09-17 00:14:23.509284 | TASK [Ensure controller directory exists]
2025-09-17 00:14:23.996181 | controller | changed
2025-09-17 00:14:24.007567 | 
2025-09-17 00:14:24.007733 | TASK [Install container runtime]
2025-09-17 00:14:24.086267 | controller | ok
2025-09-17 00:14:24.143570 | 
2025-09-17 00:14:24.143697 | LOOP [ensure-podman : Find distribution installation]
2025-09-17 00:14:24.184970 | controller | ok: "/var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-17 00:14:24.202696 | controller | included: /var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-17 00:14:24.216104 | 
2025-09-17 00:14:24.216247 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-17 00:15:41.915048 | controller | changed
2025-09-17 00:15:41.930605 | 
2025-09-17 00:15:41.930797 | TASK [ensure-podman : Fetch podman version]
2025-09-17 00:15:42.656949 | controller | Client:       Podman Engine
2025-09-17 00:15:42.657065 | controller | Version:      4.6.2
2025-09-17 00:15:42.657113 | controller | API Version:  4.6.2
2025-09-17 00:15:42.657153 | controller | Go Version:   go1.19.12
2025-09-17 00:15:42.657214 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-17 00:15:42.657271 | controller | OS/Arch:      linux/amd64
2025-09-17 00:15:43.081434 | controller | ok: Runtime: 0:00:00.206626
2025-09-17 00:15:43.095293 | 
2025-09-17 00:15:43.095446 | TASK [ensure-podman : Print podman version installed]
2025-09-17 00:15:43.134213 | Podman version: Client:       Podman Engine
2025-09-17 00:15:43.134479 | Version:      4.6.2
2025-09-17 00:15:43.134553 | API Version:  4.6.2
2025-09-17 00:15:43.134615 | Go Version:   go1.19.12
2025-09-17 00:15:43.134657 | Built:        Mon Aug 28 19:38:31 2023
2025-09-17 00:15:43.134743 | OS/Arch:      linux/amd64
2025-09-17 00:15:43.146996 | 
2025-09-17 00:15:43.147144 | TASK [ensure-podman : Validate podman engine]
2025-09-17 00:15:43.286862 | controller | skipping: Conditional result was False
2025-09-17 00:15:43.299521 | 
2025-09-17 00:15:43.299654 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-17 00:15:43.326191 | controller | skipping: Conditional result was False
2025-09-17 00:15:43.348734 | 
2025-09-17 00:15:43.348862 | TASK [Ensure python3.8 is present]
2025-09-17 00:15:43.375382 | controller | skipping: Conditional result was False
2025-09-17 00:15:43.387278 | 
2025-09-17 00:15:43.387406 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-17 00:15:43.415410 | controller | ok
2025-09-17 00:15:43.446058 | 
2025-09-17 00:15:43.446161 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-17 00:15:47.178981 | controller | ok: Nothing to do
2025-09-17 00:15:47.190864 | 
2025-09-17 00:15:47.190993 | TASK [our-ensure-python : Also install python3-devel]
2025-09-17 00:16:00.138760 | controller | changed
2025-09-17 00:16:00.161242 | 
2025-09-17 00:16:00.161370 | TASK [Run ensure-virtualenv role]
2025-09-17 00:16:00.190809 | controller | ok
2025-09-17 00:16:00.225053 | 
2025-09-17 00:16:00.225145 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-17 00:16:00.622312 | controller | /usr/bin/virtualenv
2025-09-17 00:16:00.891501 | controller | ok: Runtime: 0:00:00.005667
2025-09-17 00:16:00.903386 | 
2025-09-17 00:16:00.903527 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-17 00:16:00.940091 | controller | skipping: Conditional result was False
2025-09-17 00:16:00.940755 | controller | ok: All items complete
2025-09-17 00:16:00.940836 | 
2025-09-17 00:16:00.974135 | 
2025-09-17 00:16:00.974314 | TASK [Find the full path of the Python interpreter]
2025-09-17 00:16:01.487326 | controller | /usr/bin/python3
2025-09-17 00:16:01.616210 | controller | ok
2025-09-17 00:16:01.627747 | 
2025-09-17 00:16:01.627882 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-17 00:16:03.535240 | controller | created virtual environment CPython3.11.0.final.0-64 in 957ms
2025-09-17 00:16:03.583063 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-17 00:16:03.583122 | 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-17 00:16:03.583138 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-17 00:16:03.583163 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-17 00:16:04.038945 | controller | changed
2025-09-17 00:16:04.049765 | 
2025-09-17 00:16:04.049863 | TASK [Set selinux package]
2025-09-17 00:16:04.094913 | controller | ok
2025-09-17 00:16:04.100357 | 
2025-09-17 00:16:04.100438 | TASK [Set selinux package (Fedora)]
2025-09-17 00:16:04.145055 | controller | ok
2025-09-17 00:16:04.153742 | 
2025-09-17 00:16:04.153831 | TASK [Install selinux into virtualenv]
2025-09-17 00:16:06.785267 | controller | Collecting selinux-please-lie-to-me
2025-09-17 00:16:06.876245 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-17 00:16:07.409545 | controller | Collecting setuptools<50.0.0
2025-09-17 00:16:07.424844 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-17 00:16:07.546653 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.0 MB/s eta 0:00:00
2025-09-17 00:16:07.701745 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-17 00:16:07.702041 | controller |   Attempting uninstall: setuptools
2025-09-17 00:16:07.706956 | controller |     Found existing installation: setuptools 62.6.0
2025-09-17 00:16:07.819107 | controller |     Uninstalling setuptools-62.6.0:
2025-09-17 00:16:07.834422 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-17 00:16:08.583776 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-17 00:16:08.790358 | controller |
2025-09-17 00:16:09.008567 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-17 00:16:09.008613 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-17 00:16:09.347899 | controller | ok: Runtime: 0:00:04.378493
2025-09-17 00:16:09.362127 | 
2025-09-17 00:16:09.362279 | TASK [Install pytest-forked into virtualenv]
2025-09-17 00:16:10.582025 | controller | Collecting pytest-forked
2025-09-17 00:16:10.682638 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-17 00:16:10.741880 | controller | Collecting py
2025-09-17 00:16:10.754490 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-17 00:16:10.787959 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.5 MB/s eta 0:00:00
2025-09-17 00:16:10.966908 | controller | Collecting pytest>=3.10
2025-09-17 00:16:10.980157 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-17 00:16:11.038760 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.6 MB/s eta 0:00:00
2025-09-17 00:16:11.102292 | controller | Collecting iniconfig>=1
2025-09-17 00:16:11.114506 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-17 00:16:11.190343 | controller | Collecting packaging>=20
2025-09-17 00:16:11.202393 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-17 00:16:11.213189 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.9 MB/s eta 0:00:00
2025-09-17 00:16:11.261516 | controller | Collecting pluggy<2,>=1.5
2025-09-17 00:16:11.275109 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-17 00:16:11.350618 | controller | Collecting pygments>=2.7.2
2025-09-17 00:16:11.362091 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-17 00:16:11.475999 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 11.0 MB/s eta 0:00:00
2025-09-17 00:16:11.612136 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-17 00:16:13.852634 | 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-17 00:16:13.868485 | controller |
2025-09-17 00:16:14.060152 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-17 00:16:14.060194 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-17 00:16:14.524148 | controller | ok: Runtime: 0:00:04.205949
2025-09-17 00:16:14.538277 | 
2025-09-17 00:16:14.538415 | TASK [Update pip]
2025-09-17 00:16:15.660554 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-17 00:16:15.917181 | controller | Collecting pip
2025-09-17 00:16:16.006491 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-17 00:16:16.195389 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.5 MB/s eta 0:00:00
2025-09-17 00:16:16.346980 | controller | Installing collected packages: pip
2025-09-17 00:16:16.347390 | controller |   Attempting uninstall: pip
2025-09-17 00:16:16.351887 | controller |     Found existing installation: pip 22.2.2
2025-09-17 00:16:16.610835 | controller |     Uninstalling pip-22.2.2:
2025-09-17 00:16:16.640669 | controller |       Successfully uninstalled pip-22.2.2
2025-09-17 00:16:18.365343 | controller | Successfully installed pip-25.2
2025-09-17 00:16:18.695021 | controller | ok: Runtime: 0:00:03.504150
2025-09-17 00:16:18.703184 | 
2025-09-17 00:16:18.703284 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-17 00:16:19.227836 | controller | changed
2025-09-17 00:16:19.239086 | 
2025-09-17 00:16:19.239217 | TASK [Install ansible into virtualenv]
2025-09-17 00:16:20.341026 | controller | Processing ./src/github.com/ansible/ansible
2025-09-17 00:16:20.347611 | controller |   Installing build dependencies: started
2025-09-17 00:16:22.191840 | controller |   Installing build dependencies: finished with status 'done'
2025-09-17 00:16:22.193005 | controller |   Getting requirements to build wheel: started
2025-09-17 00:16:23.745557 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-17 00:16:24.671497 | controller |   Preparing metadata (pyproject.toml): started
2025-09-17 00:16:24.671554 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-17 00:16:24.674766 | 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-17 00:16:24.679754 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-17 00:16:24.902959 | controller | ERROR
2025-09-17 00:16:24.903231 | controller | {
2025-09-17 00:16:24.903295 | controller |   "delta": "0:00:05.137055",
2025-09-17 00:16:24.903338 | controller |   "end": "2025-09-17 00:16:24.833852",
2025-09-17 00:16:24.903375 | controller |   "msg": "non-zero return code",
2025-09-17 00:16:24.903426 | controller |   "rc": 1,
2025-09-17 00:16:24.903463 | controller |   "start": "2025-09-17 00:16:19.696797"
2025-09-17 00:16:24.903498 | controller | }
failure
2025-09-17 00:16:24.906724 | 
2025-09-17 00:16:24.906824 | PLAY RECAP
2025-09-17 00:16:24.906910 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-17 00:16:24.906953 | 
2025-09-17 00:16:25.080422 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-17 00:16:25.082315 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-17 00:16:25.761626 | 
2025-09-17 00:16:25.761902 | PLAY [all]
2025-09-17 00:16:25.783047 | 
2025-09-17 00:16:25.783132 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-17 00:16:26.545253 | controller | changed: non-zero return code
2025-09-17 00:16:26.557595 | 
2025-09-17 00:16:26.557794 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-17 00:16:26.586710 | controller | skipping: Conditional result was False
2025-09-17 00:16:26.600112 | 
2025-09-17 00:16:26.600270 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-17 00:16:26.643179 | 
2025-09-17 00:16:26.643443 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-17 00:16:26.685905 | 
2025-09-17 00:16:26.686162 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-17 00:16:26.714611 | controller | skipping: Conditional result was False
2025-09-17 00:16:26.728724 | 
2025-09-17 00:16:26.728875 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-17 00:16:26.765065 | 
2025-09-17 00:16:26.765214 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-17 00:16:26.790508 | controller | skipping: Conditional result was False
2025-09-17 00:16:26.797351 | 
2025-09-17 00:16:26.797421 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-17 00:16:26.823300 | controller | skipping: Conditional result was False
2025-09-17 00:16:26.829162 | 
2025-09-17 00:16:26.829231 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-17 00:16:26.854107 | controller | skipping: Conditional result was False
2025-09-17 00:16:26.896042 | 
2025-09-17 00:16:26.896133 | PLAY RECAP
2025-09-17 00:16:26.896199 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-17 00:16:26.896242 | 
2025-09-17 00:16:27.042175 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-17 00:16:27.044842 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-17 00:16:27.651617 | 
2025-09-17 00:16:27.651894 | PLAY [all:!appliance*]
2025-09-17 00:16:27.672982 | 
2025-09-17 00:16:27.673058 | TASK [unregister the node]
2025-09-17 00:16:27.794341 | controller | skipping: Conditional result was False
2025-09-17 00:16:27.806572 | 
2025-09-17 00:16:27.806763 | TASK [include_role : fetch-output]
2025-09-17 00:16:27.857061 | controller | ok
2025-09-17 00:16:27.892314 | 
2025-09-17 00:16:27.892406 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-17 00:16:27.969270 | controller | skipping: Conditional result was False
2025-09-17 00:16:27.981545 | 
2025-09-17 00:16:27.981742 | TASK [fetch-output : Set log path for single node]
2025-09-17 00:16:28.030767 | controller | ok
2025-09-17 00:16:28.041815 | 
2025-09-17 00:16:28.041953 | LOOP [fetch-output : Ensure local output dirs]
2025-09-17 00:16:28.517538 | controller -> localhost | ok: "/var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/work/logs"
2025-09-17 00:16:28.769345 | controller -> localhost | changed: "/var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/work/artifacts"
2025-09-17 00:16:29.003711 | controller -> localhost | changed: "/var/lib/zuul/builds/be2d6962ab6444559051d28f86ddf116/work/docs"
2025-09-17 00:16:29.014244 | 
2025-09-17 00:16:29.014315 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-17 00:16:30.195494 | controller | changed:
2025-09-17 00:16:30.196039 | controller | .d..t...... ./
2025-09-17 00:16:30.196100 | controller | cd+++++++++ controller/
2025-09-17 00:16:30.196171 | controller | changed: All items complete
2025-09-17 00:16:30.196213 | 
2025-09-17 00:16:31.286587 | controller | changed: .d..t...... ./
2025-09-17 00:16:32.327755 | controller | changed: .d..t...... ./
2025-09-17 00:16:32.343739 | 
2025-09-17 00:16:32.343885 | TASK [include_role : fetch-output-openshift]
2025-09-17 00:16:32.368641 | controller | skipping: Conditional result was False
2025-09-17 00:16:32.377342 | 
2025-09-17 00:16:32.377441 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-17 00:16:32.430576 | controller | skipping: Conditional result was False
2025-09-17 00:16:32.443490 | controller | skipping: Conditional result was False
2025-09-17 00:16:32.505397 | 
2025-09-17 00:16:32.505540 | PLAY [localhost]
2025-09-17 00:16:32.522486 | 
2025-09-17 00:16:32.522575 | TASK [Run Zuul manifest role]
2025-09-17 00:16:32.542228 | localhost | ok
2025-09-17 00:16:32.561134 | 
2025-09-17 00:16:32.561231 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-17 00:16:32.976780 | localhost | changed
2025-09-17 00:16:32.981521 | 
2025-09-17 00:16:32.981585 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-17 00:16:33.011355 | localhost | ok
2025-09-17 00:16:33.022060 | 
2025-09-17 00:16:33.022144 | TASK [Set zuul-log-path fact]
2025-09-17 00:16:33.042345 | localhost | ok
2025-09-17 00:16:33.060113 | 
2025-09-17 00:16:33.060205 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-17 00:16:33.090596 | localhost | ok
2025-09-17 00:16:33.102726 | 
2025-09-17 00:16:33.102818 | LOOP [Run upload-logs-swift role]
2025-09-17 00:16:33.149090 | localhost | Output suppressed because no_log was given
2025-09-17 00:16:33.191448 | 
2025-09-17 00:16:33.191551 | TASK [Set zuul-log-path fact]
2025-09-17 00:16:33.226660 | localhost | skipping: Conditional result was False
2025-09-17 00:16:33.233684 | 
2025-09-17 00:16:33.233776 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-17 00:16:33.696162 | localhost -> localhost | ok: Runtime: 0:00:00.009515
2025-09-17 00:16:33.701536 | 
2025-09-17 00:16:33.701604 | TASK [upload-logs-swift : Upload logs to swift]