2025-10-16 00:06:38.509990 | Job console starting...
2025-10-16 00:06:38.517986 | Updating repositories
2025-10-16 00:06:38.915526 | Preparing job workspace
2025-10-16 00:06:50.120027 | Running Ansible setup...
2025-10-16 00:06:56.826002 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-16 00:06:57.541743 | 
2025-10-16 00:06:57.541867 | PLAY [localhost]
2025-10-16 00:06:57.558216 | 
2025-10-16 00:06:57.558320 | TASK [Gathering Facts]
2025-10-16 00:06:58.593297 | localhost | ok
2025-10-16 00:06:58.622010 | 
2025-10-16 00:06:58.622182 | TASK [Setup log path fact]
2025-10-16 00:06:58.644308 | localhost | ok
2025-10-16 00:06:58.659846 | 
2025-10-16 00:06:58.659964 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-16 00:06:58.688059 | localhost | ok
2025-10-16 00:06:58.696165 | 
2025-10-16 00:06:58.696241 | TASK [emit-job-header : Print job information]
2025-10-16 00:06:58.725150 | # Job Information
2025-10-16 00:06:58.725312 | Ansible Version: 2.15.12
2025-10-16 00:06:58.725345 | Job: ansible-test-sanity-docker-milestone
2025-10-16 00:06:58.725369 | Pipeline: periodic
2025-10-16 00:06:58.725391 | Executor: ze04.softwarefactory-project.io
2025-10-16 00:06:58.725411 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-16 00:06:58.725434 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/00f/ansible/00f8cfc2c00140d2ae974c2e4f8d093d/
2025-10-16 00:06:58.725455 | Event ID: 8519b50e29354706bf9787c8921242f7
2025-10-16 00:06:58.729295 | 
2025-10-16 00:06:58.729360 | LOOP [emit-job-header : Print node information]
2025-10-16 00:06:58.830501 | localhost | ok:
2025-10-16 00:06:58.830712 | localhost | # Node Information
2025-10-16 00:06:58.830753 | localhost | Inventory Hostname: controller
2025-10-16 00:06:58.830781 | localhost | Hostname: ip-172-16-188-76
2025-10-16 00:06:58.830807 | localhost | Username: zuul-worker
2025-10-16 00:06:58.830836 | localhost | Distro: Fedora 37
2025-10-16 00:06:58.830861 | localhost | Provider: ansible-us-east-2
2025-10-16 00:06:58.830885 | localhost | Region: us-east-2
2025-10-16 00:06:58.830909 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-16 00:06:58.830932 | localhost | Product Name: t3.small
2025-10-16 00:06:58.830955 | localhost | Interface IP: 18.222.216.235
2025-10-16 00:06:58.855123 | 
2025-10-16 00:06:58.855317 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-16 00:06:59.271640 | localhost -> localhost | changed
2025-10-16 00:06:59.281117 | 
2025-10-16 00:06:59.281209 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-16 00:07:00.203466 | localhost -> localhost | changed
2025-10-16 00:07:00.229844 | 
2025-10-16 00:07:00.229921 | PLAY [all:!appliance*]
2025-10-16 00:07:00.246084 | 
2025-10-16 00:07:00.246212 | TASK [include_role : start-zuul-console]
2025-10-16 00:07:00.265438 | controller | ok
2025-10-16 00:07:00.286539 | 
2025-10-16 00:07:00.286664 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-16 00:07:00.958180 | controller | ok
2025-10-16 00:07:00.981816 | 
2025-10-16 00:07:00.981939 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-16 00:07:03.431006 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-16 00:07:03.442202 | 
2025-10-16 00:07:03.442329 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-16 00:07:03.585949 | controller | skipping: Conditional result was False
2025-10-16 00:07:03.602205 | 
2025-10-16 00:07:03.602381 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-16 00:07:03.630453 | controller | skipping: Conditional result was False
2025-10-16 00:07:03.640812 | 
2025-10-16 00:07:03.640923 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-16 00:07:03.666947 | controller | skipping: Conditional result was False
2025-10-16 00:07:03.677049 | 
2025-10-16 00:07:03.677178 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-16 00:07:03.702815 | controller | skipping: Conditional result was False
2025-10-16 00:07:03.712799 | 
2025-10-16 00:07:03.712929 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-16 00:07:03.737891 | controller | skipping: Conditional result was False
2025-10-16 00:07:03.747865 | 
2025-10-16 00:07:03.747991 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-16 00:07:03.783602 | controller | skipping: Conditional result was False
2025-10-16 00:07:03.802060 | 
2025-10-16 00:07:03.802191 | TASK [Disable Fedora Modular]
2025-10-16 00:07:04.487828 | controller | changed
2025-10-16 00:07:04.499852 | 
2025-10-16 00:07:04.500017 | TASK [Enable EPEL]
2025-10-16 00:07:04.528033 | controller | skipping: Conditional result was False
2025-10-16 00:07:04.545637 | 
2025-10-16 00:07:04.545985 | TASK [Register the RHEL node]
2025-10-16 00:07:04.719768 | 
2025-10-16 00:07:04.719924 | TASK [Show the subscription-manager status]
2025-10-16 00:07:04.937377 | controller | skipping: Conditional result was False
2025-10-16 00:07:04.952520 | 
2025-10-16 00:07:04.952720 | TASK [Enable EPEL on RHEL]
2025-10-16 00:07:05.117018 | controller | skipping: Conditional result was False
2025-10-16 00:07:05.129567 | 
2025-10-16 00:07:05.129760 | TASK [Install git and tox]
2025-10-16 00:08:27.077405 | controller | changed
2025-10-16 00:08:27.091519 | 
2025-10-16 00:08:27.091721 | TASK [include_role : prepare-workspace]
2025-10-16 00:08:27.126337 | controller | ok
2025-10-16 00:08:27.158176 | 
2025-10-16 00:08:27.158328 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-16 00:08:27.689113 | controller | ok
2025-10-16 00:08:27.706961 | 
2025-10-16 00:08:27.707204 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-16 00:08:46.298710 | controller | Output suppressed because no_log was given
2025-10-16 00:08:46.314002 | 
2025-10-16 00:08:46.314165 | TASK [include_role : prepare-workspace-openshift]
2025-10-16 00:08:46.374885 | controller | skipping: Conditional result was False
2025-10-16 00:08:46.446987 | 
2025-10-16 00:08:46.447095 | PLAY [all:!appliance]
2025-10-16 00:08:46.462382 | 
2025-10-16 00:08:46.462523 | TASK [Run add-build-sshkey role (RSA)]
2025-10-16 00:08:46.496154 | controller | ok
2025-10-16 00:08:46.552100 | 
2025-10-16 00:08:46.552287 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-16 00:08:46.882231 | controller -> localhost | ok
2025-10-16 00:08:46.889023 | 
2025-10-16 00:08:46.889107 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-16 00:08:46.921417 | controller | ok
2025-10-16 00:08:46.943130 | controller | included: /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-16 00:08:46.950549 | 
2025-10-16 00:08:46.950648 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-16 00:08:47.455233 | controller -> localhost | Generating public/private rsa key pair.
2025-10-16 00:08:47.455402 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/work/00f8cfc2c00140d2ae974c2e4f8d093d_id_rsa.
2025-10-16 00:08:47.455433 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/work/00f8cfc2c00140d2ae974c2e4f8d093d_id_rsa.pub.
2025-10-16 00:08:47.455455 | controller -> localhost | The key fingerprint is:
2025-10-16 00:08:47.455476 | controller -> localhost | SHA256:qiNisJdEtGqg2yhBQWCeA0EWY8cKycTP3Xyi+//uOss zuul-build-sshkey
2025-10-16 00:08:47.455496 | controller -> localhost | The key's randomart image is:
2025-10-16 00:08:47.455515 | controller -> localhost | +---[RSA 2048]----+
2025-10-16 00:08:47.455535 | controller -> localhost | |@%o.             |
2025-10-16 00:08:47.455555 | controller -> localhost | |O+=.             |
2025-10-16 00:08:47.455574 | controller -> localhost | |.==.. o          |
2025-10-16 00:08:47.455592 | controller -> localhost | |.o+o . + .       |
2025-10-16 00:08:47.455610 | controller -> localhost | |+o    . S        |
2025-10-16 00:08:47.455639 | controller -> localhost | |=..  . .         |
2025-10-16 00:08:47.455673 | controller -> localhost | |oB .  o          |
2025-10-16 00:08:47.455747 | controller -> localhost | |*.= .o  ..       |
2025-10-16 00:08:47.455776 | controller -> localhost | |oo ......EB+     |
2025-10-16 00:08:47.455800 | controller -> localhost | +----[SHA256]-----+
2025-10-16 00:08:47.455845 | controller -> localhost | ok: Runtime: 0:00:00.131075
2025-10-16 00:08:47.462219 | 
2025-10-16 00:08:47.462299 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-16 00:08:47.482441 | controller | ok
2025-10-16 00:08:47.493400 | controller | included: /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-16 00:08:47.503378 | 
2025-10-16 00:08:47.503513 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-16 00:08:47.518309 | controller | skipping: Conditional result was False
2025-10-16 00:08:47.526609 | 
2025-10-16 00:08:47.526729 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-16 00:08:48.173569 | controller | changed
2025-10-16 00:08:48.194548 | 
2025-10-16 00:08:48.194725 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-16 00:08:48.550745 | controller | ok
2025-10-16 00:08:48.565080 | 
2025-10-16 00:08:48.565275 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-16 00:08:50.100160 | controller | changed
2025-10-16 00:08:50.109374 | 
2025-10-16 00:08:50.109513 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-16 00:08:51.416749 | controller | changed
2025-10-16 00:08:51.427901 | 
2025-10-16 00:08:51.428022 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-16 00:08:51.454040 | controller | skipping: Conditional result was False
2025-10-16 00:08:51.464816 | 
2025-10-16 00:08:51.464935 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-16 00:08:51.919380 | controller -> localhost | changed
2025-10-16 00:08:51.931047 | 
2025-10-16 00:08:51.931116 | TASK [add-build-sshkey : Add back temp key]
2025-10-16 00:08:52.271920 | controller -> localhost | Identity added: /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/work/00f8cfc2c00140d2ae974c2e4f8d093d_id_rsa (zuul-build-sshkey)
2025-10-16 00:08:52.272217 | controller -> localhost | ok: Runtime: 0:00:00.010590
2025-10-16 00:08:52.282555 | 
2025-10-16 00:08:52.282671 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-16 00:08:52.842591 | controller | ok
2025-10-16 00:08:52.849049 | 
2025-10-16 00:08:52.849123 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-16 00:08:52.875177 | controller | skipping: Conditional result was False
2025-10-16 00:08:52.887786 | 
2025-10-16 00:08:52.887938 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-16 00:08:52.919457 | controller | ok
2025-10-16 00:08:52.936308 | 
2025-10-16 00:08:52.936388 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-16 00:08:53.185229 | controller -> localhost | ok
2025-10-16 00:08:53.192947 | 
2025-10-16 00:08:53.193044 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-16 00:08:53.246088 | controller | ok
2025-10-16 00:08:53.257103 | controller | included: /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-16 00:08:53.263458 | 
2025-10-16 00:08:53.263533 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-16 00:08:53.609468 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-16 00:08:53.609719 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/work/00f8cfc2c00140d2ae974c2e4f8d093d_id_ecdsa.
2025-10-16 00:08:53.609766 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/work/00f8cfc2c00140d2ae974c2e4f8d093d_id_ecdsa.pub.
2025-10-16 00:08:53.609811 | controller -> localhost | The key fingerprint is:
2025-10-16 00:08:53.609844 | controller -> localhost | SHA256:74IMXdvef/NEisX4kgFNtv5y5rt/xtVGAl3Ebm8LrJg zuul-build-sshkey
2025-10-16 00:08:53.609878 | controller -> localhost | The key's randomart image is:
2025-10-16 00:08:53.609907 | controller -> localhost | +---[ECDSA 521]---+
2025-10-16 00:08:53.609936 | controller -> localhost | |            o. +o|
2025-10-16 00:08:53.609965 | controller -> localhost | |           +... .|
2025-10-16 00:08:53.609993 | controller -> localhost | |          . o. . |
2025-10-16 00:08:53.610021 | controller -> localhost | |        .  o o. +|
2025-10-16 00:08:53.610050 | controller -> localhost | |     . .So  = o++|
2025-10-16 00:08:53.610077 | controller -> localhost | |    . . ...  X o*|
2025-10-16 00:08:53.610105 | controller -> localhost | |     o . .+.* B++|
2025-10-16 00:08:53.610133 | controller -> localhost | |      o .E...* +=|
2025-10-16 00:08:53.610162 | controller -> localhost | |         ..  .=**|
2025-10-16 00:08:53.610190 | controller -> localhost | +----[SHA256]-----+
2025-10-16 00:08:53.610257 | controller -> localhost | ok: Runtime: 0:00:00.016147
2025-10-16 00:08:53.620997 | 
2025-10-16 00:08:53.621165 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-16 00:08:53.654604 | controller | ok
2025-10-16 00:08:53.662809 | controller | included: /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-16 00:08:53.672397 | 
2025-10-16 00:08:53.672517 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-16 00:08:53.688051 | controller | skipping: Conditional result was False
2025-10-16 00:08:53.695827 | 
2025-10-16 00:08:53.695927 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-16 00:08:54.178153 | controller | changed
2025-10-16 00:08:54.193929 | 
2025-10-16 00:08:54.194125 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-16 00:08:54.583066 | controller | ok
2025-10-16 00:08:54.595733 | 
2025-10-16 00:08:54.595927 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-16 00:08:55.921518 | controller | changed
2025-10-16 00:08:55.929482 | 
2025-10-16 00:08:55.929567 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-16 00:08:57.187140 | controller | changed
2025-10-16 00:08:57.203001 | 
2025-10-16 00:08:57.203198 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-16 00:08:57.245517 | controller | skipping: Conditional result was False
2025-10-16 00:08:57.253165 | 
2025-10-16 00:08:57.253268 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-16 00:08:57.522820 | controller -> localhost | changed
2025-10-16 00:08:57.536361 | 
2025-10-16 00:08:57.536478 | TASK [add-build-sshkey : Add back temp key]
2025-10-16 00:08:57.909089 | controller -> localhost | Identity added: /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/work/00f8cfc2c00140d2ae974c2e4f8d093d_id_ecdsa (zuul-build-sshkey)
2025-10-16 00:08:57.909275 | controller -> localhost | ok: Runtime: 0:00:00.009469
2025-10-16 00:08:57.921673 | 
2025-10-16 00:08:57.921824 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-16 00:08:58.263397 | controller | ok
2025-10-16 00:08:58.276332 | 
2025-10-16 00:08:58.279748 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-16 00:08:58.315853 | controller | skipping: Conditional result was False
2025-10-16 00:08:58.328009 | 
2025-10-16 00:08:58.328129 | TASK [include_role : remove-zuul-sshkey]
2025-10-16 00:08:58.353241 | controller | skipping: Conditional result was False
2025-10-16 00:08:58.360319 | 
2025-10-16 00:08:58.360456 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-16 00:08:58.682967 | controller | ok: "logs"
2025-10-16 00:08:58.683205 | controller | ok: All items complete
2025-10-16 00:08:58.683238 | 
2025-10-16 00:08:58.963857 | controller | ok: "artifacts"
2025-10-16 00:08:59.274540 | controller | ok: "docs"
2025-10-16 00:08:59.289260 | 
2025-10-16 00:08:59.289437 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-16 00:08:59.621300 | controller | changed: "logs"
2025-10-16 00:08:59.931950 | controller | changed: "artifacts"
2025-10-16 00:09:00.309269 | controller | changed: "docs"
2025-10-16 00:09:00.346262 | 
2025-10-16 00:09:00.346525 | PLAY RECAP
2025-10-16 00:09:00.346585 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-16 00:09:00.346623 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-16 00:09:00.346651 | 
2025-10-16 00:09:00.461670 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-16 00:09:00.462849 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-16 00:09:01.080142 | 
2025-10-16 00:09:01.080266 | PLAY [all]
2025-10-16 00:09:01.104739 | 
2025-10-16 00:09:01.104866 | TASK [Install binary dependencies]
2025-10-16 00:09:01.156962 | controller | ok
2025-10-16 00:09:01.179703 | 
2025-10-16 00:09:01.179833 | TASK [bindep : Include find tasks]
2025-10-16 00:09:01.219219 | controller | ok
2025-10-16 00:09:01.227210 | controller | included: /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-16 00:09:01.233371 | 
2025-10-16 00:09:01.233484 | TASK [bindep : Look for bindep.txt]
2025-10-16 00:09:02.043006 | controller | ok
2025-10-16 00:09:02.052897 | 
2025-10-16 00:09:02.053005 | TASK [bindep : Define bindep_file fact]
2025-10-16 00:09:02.078876 | controller | skipping: Conditional result was False
2025-10-16 00:09:02.088646 | 
2025-10-16 00:09:02.088803 | TASK [bindep : Look for other-requirements.txt]
2025-10-16 00:09:02.742030 | controller | ok
2025-10-16 00:09:02.751408 | 
2025-10-16 00:09:02.751516 | TASK [bindep : Define bindep_file fact]
2025-10-16 00:09:02.787743 | controller | skipping: Conditional result was False
2025-10-16 00:09:02.801519 | 
2025-10-16 00:09:02.801665 | TASK [bindep : Look for bindep fallback file]
2025-10-16 00:09:02.839043 | controller | skipping: Conditional result was False
2025-10-16 00:09:02.857342 | 
2025-10-16 00:09:02.857502 | TASK [bindep : Define bindep_file fact]
2025-10-16 00:09:02.906206 | controller | skipping: Conditional result was False
2025-10-16 00:09:02.914471 | 
2025-10-16 00:09:02.914565 | TASK [bindep : Include bindep tasks]
2025-10-16 00:09:02.949620 | controller | skipping: Conditional result was False
2025-10-16 00:09:02.959884 | 
2025-10-16 00:09:02.959983 | TASK [bindep : Include install tasks]
2025-10-16 00:09:02.995799 | controller | skipping: Conditional result was False
2025-10-16 00:09:03.004483 | 
2025-10-16 00:09:03.004591 | LOOP [bindep : Include package tasks]
2025-10-16 00:09:03.089362 | 
2025-10-16 00:09:03.089653 | TASK [Run test-setup role]
2025-10-16 00:09:03.123003 | controller | ok
2025-10-16 00:09:03.149340 | 
2025-10-16 00:09:03.149453 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-16 00:09:03.512614 | controller | ok
2025-10-16 00:09:03.525367 | 
2025-10-16 00:09:03.525523 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-16 00:09:03.679256 | controller | skipping: Conditional result was False
2025-10-16 00:09:03.733835 | 
2025-10-16 00:09:03.733977 | PLAY RECAP
2025-10-16 00:09:03.734038 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-16 00:09:03.734068 | 
2025-10-16 00:09:03.889960 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-16 00:09:03.891161 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-16 00:09:04.535608 | 
2025-10-16 00:09:04.535776 | PLAY [controller]
2025-10-16 00:09:04.555657 | 
2025-10-16 00:09:04.555808 | TASK [Create the /root directory]
2025-10-16 00:09:05.311275 | controller | ok
2025-10-16 00:09:05.324013 | 
2025-10-16 00:09:05.324111 | TASK [Install glibc-langpack-en]
2025-10-16 00:09:13.405401 | controller | ok: Nothing to do
2025-10-16 00:09:13.420870 | 
2025-10-16 00:09:13.421088 | TASK [Ensure controller directory exists]
2025-10-16 00:09:13.900317 | controller | changed
2025-10-16 00:09:13.913330 | 
2025-10-16 00:09:13.913494 | TASK [Install container runtime]
2025-10-16 00:09:13.998118 | controller | ok
2025-10-16 00:09:14.056429 | 
2025-10-16 00:09:14.056562 | LOOP [ensure-podman : Find distribution installation]
2025-10-16 00:09:14.084216 | controller | ok: "/var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-16 00:09:14.100081 | controller | included: /var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-16 00:09:14.107256 | 
2025-10-16 00:09:14.107388 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-16 00:10:29.847045 | controller | changed
2025-10-16 00:10:29.857113 | 
2025-10-16 00:10:29.857254 | TASK [ensure-podman : Fetch podman version]
2025-10-16 00:10:30.597856 | controller | Client:       Podman Engine
2025-10-16 00:10:30.597961 | controller | Version:      4.6.2
2025-10-16 00:10:30.598004 | controller | API Version:  4.6.2
2025-10-16 00:10:30.598064 | controller | Go Version:   go1.19.12
2025-10-16 00:10:30.598120 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-16 00:10:30.598164 | controller | OS/Arch:      linux/amd64
2025-10-16 00:10:31.002591 | controller | ok: Runtime: 0:00:00.220522
2025-10-16 00:10:31.011708 | 
2025-10-16 00:10:31.011824 | TASK [ensure-podman : Print podman version installed]
2025-10-16 00:10:31.043956 | Podman version: Client:       Podman Engine
2025-10-16 00:10:31.044125 | Version:      4.6.2
2025-10-16 00:10:31.044156 | API Version:  4.6.2
2025-10-16 00:10:31.044183 | Go Version:   go1.19.12
2025-10-16 00:10:31.044207 | Built:        Mon Aug 28 19:38:31 2023
2025-10-16 00:10:31.044229 | OS/Arch:      linux/amd64
2025-10-16 00:10:31.050685 | 
2025-10-16 00:10:31.050779 | TASK [ensure-podman : Validate podman engine]
2025-10-16 00:10:31.182750 | controller | skipping: Conditional result was False
2025-10-16 00:10:31.189020 | 
2025-10-16 00:10:31.189101 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-16 00:10:31.203752 | controller | skipping: Conditional result was False
2025-10-16 00:10:31.219882 | 
2025-10-16 00:10:31.219997 | TASK [Ensure python3.8 is present]
2025-10-16 00:10:31.244694 | controller | skipping: Conditional result was False
2025-10-16 00:10:31.251750 | 
2025-10-16 00:10:31.251832 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-16 00:10:31.273048 | controller | ok
2025-10-16 00:10:31.314592 | 
2025-10-16 00:10:31.314888 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-16 00:10:35.063339 | controller | ok: Nothing to do
2025-10-16 00:10:35.073042 | 
2025-10-16 00:10:35.073143 | TASK [our-ensure-python : Also install python3-devel]
2025-10-16 00:10:48.227439 | controller | changed
2025-10-16 00:10:48.264359 | 
2025-10-16 00:10:48.264502 | TASK [Run ensure-virtualenv role]
2025-10-16 00:10:48.290967 | controller | ok
2025-10-16 00:10:48.342787 | 
2025-10-16 00:10:48.343746 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-16 00:10:48.712575 | controller | /usr/bin/virtualenv
2025-10-16 00:10:48.979899 | controller | ok: Runtime: 0:00:00.004371
2025-10-16 00:10:48.987180 | 
2025-10-16 00:10:48.987266 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-16 00:10:49.016994 | controller | skipping: Conditional result was False
2025-10-16 00:10:49.017270 | controller | ok: All items complete
2025-10-16 00:10:49.017301 | 
2025-10-16 00:10:49.039875 | 
2025-10-16 00:10:49.040021 | TASK [Find the full path of the Python interpreter]
2025-10-16 00:10:49.496852 | controller | /usr/bin/python3
2025-10-16 00:10:49.724170 | controller | ok
2025-10-16 00:10:49.730635 | 
2025-10-16 00:10:49.730809 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-16 00:10:51.165111 | controller | created virtual environment CPython3.11.0.final.0-64 in 796ms
2025-10-16 00:10:51.208586 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-16 00:10:51.208642 | 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-16 00:10:51.208660 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-16 00:10:51.208685 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-16 00:10:51.362812 | controller | changed
2025-10-16 00:10:51.369364 | 
2025-10-16 00:10:51.369439 | TASK [Set selinux package]
2025-10-16 00:10:51.399104 | controller | ok
2025-10-16 00:10:51.404324 | 
2025-10-16 00:10:51.404400 | TASK [Set selinux package (Fedora)]
2025-10-16 00:10:51.435916 | controller | ok
2025-10-16 00:10:51.441700 | 
2025-10-16 00:10:51.441780 | TASK [Install selinux into virtualenv]
2025-10-16 00:10:54.069317 | controller | Collecting selinux-please-lie-to-me
2025-10-16 00:10:54.238509 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-16 00:10:54.763212 | controller | Collecting setuptools<50.0.0
2025-10-16 00:10:54.783107 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-16 00:10:54.880992 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 8.7 MB/s eta 0:00:00
2025-10-16 00:10:55.036321 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-16 00:10:55.036740 | controller |   Attempting uninstall: setuptools
2025-10-16 00:10:55.041711 | controller |     Found existing installation: setuptools 62.6.0
2025-10-16 00:10:55.154944 | controller |     Uninstalling setuptools-62.6.0:
2025-10-16 00:10:55.170039 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-16 00:10:55.912503 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-16 00:10:56.124685 | controller |
2025-10-16 00:10:56.339058 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-16 00:10:56.339106 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-16 00:10:56.842498 | controller | ok: Runtime: 0:00:04.428032
2025-10-16 00:10:56.848132 | 
2025-10-16 00:10:56.848197 | TASK [Install pytest-forked into virtualenv]
2025-10-16 00:10:58.055881 | controller | Collecting pytest-forked
2025-10-16 00:10:58.142223 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-16 00:10:58.198739 | controller | Collecting py
2025-10-16 00:10:58.210928 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-16 00:10:58.246294 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00
2025-10-16 00:10:58.419714 | controller | Collecting pytest>=3.10
2025-10-16 00:10:58.438550 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-16 00:10:58.496646 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.5 MB/s eta 0:00:00
2025-10-16 00:10:58.550620 | controller | Collecting iniconfig>=1
2025-10-16 00:10:58.562546 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-16 00:10:58.629891 | controller | Collecting packaging>=20
2025-10-16 00:10:58.642036 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-16 00:10:58.654120 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.8 MB/s eta 0:00:00
2025-10-16 00:10:58.702567 | controller | Collecting pluggy<2,>=1.5
2025-10-16 00:10:58.714430 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-16 00:10:58.787242 | controller | Collecting pygments>=2.7.2
2025-10-16 00:10:58.799361 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-16 00:10:58.915808 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.7 MB/s eta 0:00:00
2025-10-16 00:10:59.045316 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-16 00:11:01.368407 | 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-10-16 00:11:01.387746 | controller |
2025-10-16 00:11:01.583004 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-16 00:11:01.583072 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-16 00:11:01.998572 | controller | ok: Runtime: 0:00:04.265860
2025-10-16 00:11:02.011487 | 
2025-10-16 00:11:02.011638 | TASK [Update pip]
2025-10-16 00:11:03.809154 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-16 00:11:04.052999 | controller | Collecting pip
2025-10-16 00:11:04.149971 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-16 00:11:04.360938 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.5 MB/s eta 0:00:00
2025-10-16 00:11:04.527248 | controller | Installing collected packages: pip
2025-10-16 00:11:04.527564 | controller |   Attempting uninstall: pip
2025-10-16 00:11:04.532075 | controller |     Found existing installation: pip 22.2.2
2025-10-16 00:11:04.797337 | controller |     Uninstalling pip-22.2.2:
2025-10-16 00:11:04.827268 | controller |       Successfully uninstalled pip-22.2.2
2025-10-16 00:11:06.597236 | controller | Successfully installed pip-25.2
2025-10-16 00:11:07.200357 | controller | ok: Runtime: 0:00:04.158264
2025-10-16 00:11:07.206285 | 
2025-10-16 00:11:07.206352 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-16 00:11:07.746072 | controller | changed
2025-10-16 00:11:07.751265 | 
2025-10-16 00:11:07.751326 | TASK [Install ansible into virtualenv]
2025-10-16 00:11:08.898438 | controller | Processing ./src/github.com/ansible/ansible
2025-10-16 00:11:08.904752 | controller |   Installing build dependencies: started
2025-10-16 00:11:10.748858 | controller |   Installing build dependencies: finished with status 'done'
2025-10-16 00:11:12.404208 | controller |   Getting requirements to build wheel: started
2025-10-16 00:11:12.404274 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-16 00:11:12.405687 | controller |   Preparing metadata (pyproject.toml): started
2025-10-16 00:11:13.335169 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-16 00:11:13.346090 | 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-16 00:11:13.493309 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-16 00:11:13.921453 | controller | ERROR
2025-10-16 00:11:13.921616 | controller | {
2025-10-16 00:11:13.921646 | controller |   "delta": "0:00:05.281464",
2025-10-16 00:11:13.921667 | controller |   "end": "2025-10-16 00:11:13.493876",
2025-10-16 00:11:13.921729 | controller |   "msg": "non-zero return code",
2025-10-16 00:11:13.921759 | controller |   "rc": 1,
2025-10-16 00:11:13.921778 | controller |   "start": "2025-10-16 00:11:08.212412"
2025-10-16 00:11:13.921796 | controller | }
failure
2025-10-16 00:11:13.933613 | 
2025-10-16 00:11:13.933735 | PLAY RECAP
2025-10-16 00:11:13.933793 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-16 00:11:13.933817 | 
2025-10-16 00:11:14.056229 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-16 00:11:14.057266 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-16 00:11:14.647277 | 
2025-10-16 00:11:14.647390 | PLAY [all]
2025-10-16 00:11:14.671572 | 
2025-10-16 00:11:14.671696 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-16 00:11:15.430472 | controller | changed: non-zero return code
2025-10-16 00:11:15.436442 | 
2025-10-16 00:11:15.436530 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-16 00:11:15.461550 | controller | skipping: Conditional result was False
2025-10-16 00:11:15.470244 | 
2025-10-16 00:11:15.470374 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-16 00:11:15.503629 | 
2025-10-16 00:11:15.503811 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-16 00:11:15.535037 | 
2025-10-16 00:11:15.535350 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-16 00:11:15.559736 | controller | skipping: Conditional result was False
2025-10-16 00:11:15.566426 | 
2025-10-16 00:11:15.566511 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-16 00:11:15.598076 | 
2025-10-16 00:11:15.598271 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-16 00:11:15.613733 | controller | skipping: Conditional result was False
2025-10-16 00:11:15.620342 | 
2025-10-16 00:11:15.620423 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-16 00:11:15.645326 | controller | skipping: Conditional result was False
2025-10-16 00:11:15.652363 | 
2025-10-16 00:11:15.652433 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-16 00:11:15.666662 | controller | skipping: Conditional result was False
2025-10-16 00:11:15.698919 | 
2025-10-16 00:11:15.699109 | PLAY RECAP
2025-10-16 00:11:15.699176 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-16 00:11:15.699207 | 
2025-10-16 00:11:15.900444 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-16 00:11:15.901602 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-16 00:11:16.488833 | 
2025-10-16 00:11:16.488964 | PLAY [all:!appliance*]
2025-10-16 00:11:16.522838 | 
2025-10-16 00:11:16.522975 | TASK [unregister the node]
2025-10-16 00:11:16.656832 | controller | skipping: Conditional result was False
2025-10-16 00:11:16.669891 | 
2025-10-16 00:11:16.670091 | TASK [include_role : fetch-output]
2025-10-16 00:11:16.704692 | controller | ok
2025-10-16 00:11:16.735426 | 
2025-10-16 00:11:16.735562 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-16 00:11:16.802788 | controller | skipping: Conditional result was False
2025-10-16 00:11:16.811505 | 
2025-10-16 00:11:16.811667 | TASK [fetch-output : Set log path for single node]
2025-10-16 00:11:16.861273 | controller | ok
2025-10-16 00:11:16.866874 | 
2025-10-16 00:11:16.866958 | LOOP [fetch-output : Ensure local output dirs]
2025-10-16 00:11:17.282660 | controller -> localhost | ok: "/var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/work/logs"
2025-10-16 00:11:17.516271 | controller -> localhost | changed: "/var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/work/artifacts"
2025-10-16 00:11:17.770260 | controller -> localhost | changed: "/var/lib/zuul/builds/00f8cfc2c00140d2ae974c2e4f8d093d/work/docs"
2025-10-16 00:11:17.787667 | 
2025-10-16 00:11:17.787798 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-16 00:11:19.043282 | controller | changed:
2025-10-16 00:11:19.043516 | controller | .d..t...... ./
2025-10-16 00:11:19.043559 | controller | cd+++++++++ controller/
2025-10-16 00:11:19.043623 | controller | changed: All items complete
2025-10-16 00:11:19.043657 | 
2025-10-16 00:11:20.006745 | controller | changed: .d..t...... ./
2025-10-16 00:11:21.010050 | controller | changed: .d..t...... ./
2025-10-16 00:11:21.029899 | 
2025-10-16 00:11:21.030029 | TASK [include_role : fetch-output-openshift]
2025-10-16 00:11:21.046588 | controller | skipping: Conditional result was False
2025-10-16 00:11:21.054550 | 
2025-10-16 00:11:21.054668 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-16 00:11:21.080949 | controller | skipping: Conditional result was False
2025-10-16 00:11:21.090068 | controller | skipping: Conditional result was False
2025-10-16 00:11:21.120495 | 
2025-10-16 00:11:21.120602 | PLAY [localhost]
2025-10-16 00:11:21.134619 | 
2025-10-16 00:11:21.134738 | TASK [Run Zuul manifest role]
2025-10-16 00:11:21.153558 | localhost | ok
2025-10-16 00:11:21.168188 | 
2025-10-16 00:11:21.168301 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-16 00:11:21.535544 | localhost | changed
2025-10-16 00:11:21.540551 | 
2025-10-16 00:11:21.540618 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-16 00:11:21.569450 | localhost | ok
2025-10-16 00:11:21.577487 | 
2025-10-16 00:11:21.577573 | TASK [Set zuul-log-path fact]
2025-10-16 00:11:21.597215 | localhost | ok
2025-10-16 00:11:21.615997 | 
2025-10-16 00:11:21.616128 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-16 00:11:21.663052 | localhost | ok
2025-10-16 00:11:21.674479 | 
2025-10-16 00:11:21.674571 | LOOP [Run upload-logs-swift role]
2025-10-16 00:11:21.709349 | localhost | Output suppressed because no_log was given
2025-10-16 00:11:21.743836 | 
2025-10-16 00:11:21.744140 | TASK [Set zuul-log-path fact]
2025-10-16 00:11:21.768658 | localhost | skipping: Conditional result was False
2025-10-16 00:11:21.775741 | 
2025-10-16 00:11:21.775839 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-16 00:11:22.187046 | localhost -> localhost | ok: Runtime: 0:00:00.011063
2025-10-16 00:11:22.202413 | 
2025-10-16 00:11:22.202598 | TASK [upload-logs-swift : Upload logs to swift]