2025-10-11 00:17:00.572914 | Job console starting...
2025-10-11 00:17:00.581560 | Updating repositories
2025-10-11 00:17:00.704376 | Preparing job workspace
2025-10-11 00:17:04.717939 | Running Ansible setup...
2025-10-11 00:17:10.672734 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-11 00:17:11.325525 | 
2025-10-11 00:17:11.325767 | PLAY [localhost]
2025-10-11 00:17:11.334774 | 
2025-10-11 00:17:11.334847 | TASK [Gathering Facts]
2025-10-11 00:17:12.349479 | localhost | ok
2025-10-11 00:17:12.379057 | 
2025-10-11 00:17:12.379218 | TASK [Setup log path fact]
2025-10-11 00:17:12.401221 | localhost | ok
2025-10-11 00:17:12.417481 | 
2025-10-11 00:17:12.417574 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-11 00:17:12.456606 | localhost | ok
2025-10-11 00:17:12.467201 | 
2025-10-11 00:17:12.467295 | TASK [emit-job-header : Print job information]
2025-10-11 00:17:12.517841 | # Job Information
2025-10-11 00:17:12.518028 | Ansible Version: 2.15.12
2025-10-11 00:17:12.518070 | Job: ansible-test-sanity-docker-milestone
2025-10-11 00:17:12.518099 | Pipeline: periodic
2025-10-11 00:17:12.518125 | Executor: ze04.softwarefactory-project.io
2025-10-11 00:17:12.518150 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-11 00:17:12.518179 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/de7/ansible/de7ebd89e446428ba4a8a4e5656b31a1/
2025-10-11 00:17:12.518205 | Event ID: d6ccd92d500144d2bcd347dd8f427b4a
2025-10-11 00:17:12.523303 | 
2025-10-11 00:17:12.523384 | LOOP [emit-job-header : Print node information]
2025-10-11 00:17:12.647368 | localhost | ok:
2025-10-11 00:17:12.647667 | localhost | # Node Information
2025-10-11 00:17:12.647798 | localhost | Inventory Hostname: controller
2025-10-11 00:17:12.647850 | localhost | Hostname: ip-172-16-113-157
2025-10-11 00:17:12.647896 | localhost | Username: zuul-worker
2025-10-11 00:17:12.647945 | localhost | Distro: Fedora 37
2025-10-11 00:17:12.647991 | localhost | Provider: ansible-us-east-2
2025-10-11 00:17:12.648032 | localhost | Region: us-east-2
2025-10-11 00:17:12.648073 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-11 00:17:12.648113 | localhost | Product Name: t3.small
2025-10-11 00:17:12.648154 | localhost | Interface IP: 52.15.183.64
2025-10-11 00:17:12.665753 | 
2025-10-11 00:17:12.665949 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-11 00:17:13.120728 | localhost -> localhost | changed
2025-10-11 00:17:13.128605 | 
2025-10-11 00:17:13.128732 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-11 00:17:14.113363 | localhost -> localhost | changed
2025-10-11 00:17:14.151269 | 
2025-10-11 00:17:14.151374 | PLAY [all:!appliance*]
2025-10-11 00:17:14.172837 | 
2025-10-11 00:17:14.172933 | TASK [include_role : start-zuul-console]
2025-10-11 00:17:14.215226 | controller | ok
2025-10-11 00:17:14.234331 | 
2025-10-11 00:17:14.234438 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-11 00:17:14.891838 | controller | ok
2025-10-11 00:17:14.908310 | 
2025-10-11 00:17:14.908468 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-11 00:17:16.608506 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-11 00:17:16.615194 | 
2025-10-11 00:17:16.615276 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-11 00:17:16.759344 | controller | skipping: Conditional result was False
2025-10-11 00:17:16.768911 | 
2025-10-11 00:17:16.769072 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-11 00:17:16.796416 | controller | skipping: Conditional result was False
2025-10-11 00:17:16.808078 | 
2025-10-11 00:17:16.808180 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-11 00:17:16.834481 | controller | skipping: Conditional result was False
2025-10-11 00:17:16.844157 | 
2025-10-11 00:17:16.844258 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-11 00:17:16.870925 | controller | skipping: Conditional result was False
2025-10-11 00:17:16.890804 | 
2025-10-11 00:17:16.890921 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-11 00:17:16.918341 | controller | skipping: Conditional result was False
2025-10-11 00:17:16.928973 | 
2025-10-11 00:17:16.929070 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-11 00:17:16.956035 | controller | skipping: Conditional result was False
2025-10-11 00:17:16.976441 | 
2025-10-11 00:17:16.976614 | TASK [Disable Fedora Modular]
2025-10-11 00:17:17.667395 | controller | changed
2025-10-11 00:17:17.678568 | 
2025-10-11 00:17:17.678746 | TASK [Enable EPEL]
2025-10-11 00:17:17.705553 | controller | skipping: Conditional result was False
2025-10-11 00:17:17.718158 | 
2025-10-11 00:17:17.718508 | TASK [Register the RHEL node]
2025-10-11 00:17:17.878898 | 
2025-10-11 00:17:17.879230 | TASK [Show the subscription-manager status]
2025-10-11 00:17:18.074570 | controller | skipping: Conditional result was False
2025-10-11 00:17:18.082047 | 
2025-10-11 00:17:18.082131 | TASK [Enable EPEL on RHEL]
2025-10-11 00:17:18.220590 | controller | skipping: Conditional result was False
2025-10-11 00:17:18.233212 | 
2025-10-11 00:17:18.233357 | TASK [Install git and tox]
2025-10-11 00:18:53.362774 | controller | changed
2025-10-11 00:18:53.371060 | 
2025-10-11 00:18:53.371163 | TASK [include_role : prepare-workspace]
2025-10-11 00:18:53.405783 | controller | ok
2025-10-11 00:18:53.437444 | 
2025-10-11 00:18:53.437605 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-11 00:18:53.972378 | controller | ok
2025-10-11 00:18:53.986476 | 
2025-10-11 00:18:53.986659 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-11 00:19:07.617078 | controller | Output suppressed because no_log was given
2025-10-11 00:19:07.632867 | 
2025-10-11 00:19:07.632942 | TASK [include_role : prepare-workspace-openshift]
2025-10-11 00:19:07.669022 | controller | skipping: Conditional result was False
2025-10-11 00:19:07.700109 | 
2025-10-11 00:19:07.700198 | PLAY [all:!appliance]
2025-10-11 00:19:07.782124 | 
2025-10-11 00:19:07.782298 | TASK [Run add-build-sshkey role (RSA)]
2025-10-11 00:19:07.815427 | controller | ok
2025-10-11 00:19:07.835743 | 
2025-10-11 00:19:07.835897 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-11 00:19:08.117988 | controller -> localhost | ok
2025-10-11 00:19:08.125830 | 
2025-10-11 00:19:08.125901 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-11 00:19:08.160330 | controller | ok
2025-10-11 00:19:08.180935 | controller | included: /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-11 00:19:08.188516 | 
2025-10-11 00:19:08.188590 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-11 00:19:08.633925 | controller -> localhost | Generating public/private rsa key pair.
2025-10-11 00:19:08.634165 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/work/de7ebd89e446428ba4a8a4e5656b31a1_id_rsa.
2025-10-11 00:19:08.634199 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/work/de7ebd89e446428ba4a8a4e5656b31a1_id_rsa.pub.
2025-10-11 00:19:08.634221 | controller -> localhost | The key fingerprint is:
2025-10-11 00:19:08.634239 | controller -> localhost | SHA256:v6hUjLUijAidXUGvUFCpo9I+u7MupR0pouT7/5/xMoU zuul-build-sshkey
2025-10-11 00:19:08.634258 | controller -> localhost | The key's randomart image is:
2025-10-11 00:19:08.634278 | controller -> localhost | +---[RSA 2048]----+
2025-10-11 00:19:08.634301 | controller -> localhost | |    .+*o         |
2025-10-11 00:19:08.634320 | controller -> localhost | | . o o..         |
2025-10-11 00:19:08.634338 | controller -> localhost | |. o o.  o        |
2025-10-11 00:19:08.634356 | controller -> localhost | |.. oo. = .       |
2025-10-11 00:19:08.634373 | controller -> localhost | |...oo.+ S .      |
2025-10-11 00:19:08.634402 | controller -> localhost | |+.*  . o E .     |
2025-10-11 00:19:08.634430 | controller -> localhost | |=B .  .  .o      |
2025-10-11 00:19:08.634449 | controller -> localhost | |+.=  .   ++.     |
2025-10-11 00:19:08.634466 | controller -> localhost | | +BB..oooo+.     |
2025-10-11 00:19:08.634487 | controller -> localhost | +----[SHA256]-----+
2025-10-11 00:19:08.634539 | controller -> localhost | ok: Runtime: 0:00:00.062014
2025-10-11 00:19:08.644232 | 
2025-10-11 00:19:08.644303 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-11 00:19:08.675391 | controller | ok
2025-10-11 00:19:08.688370 | controller | included: /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-11 00:19:08.701305 | 
2025-10-11 00:19:08.701378 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-11 00:19:08.726978 | controller | skipping: Conditional result was False
2025-10-11 00:19:08.739693 | 
2025-10-11 00:19:08.740491 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-11 00:19:09.416642 | controller | changed
2025-10-11 00:19:09.432222 | 
2025-10-11 00:19:09.432339 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-11 00:19:09.826305 | controller | ok
2025-10-11 00:19:09.836377 | 
2025-10-11 00:19:09.836468 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-11 00:19:11.291820 | controller | changed
2025-10-11 00:19:11.300539 | 
2025-10-11 00:19:11.300640 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-11 00:19:12.607029 | controller | changed
2025-10-11 00:19:12.617034 | 
2025-10-11 00:19:12.617102 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-11 00:19:12.652181 | controller | skipping: Conditional result was False
2025-10-11 00:19:12.661232 | 
2025-10-11 00:19:12.661359 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-11 00:19:13.105547 | controller -> localhost | changed
2025-10-11 00:19:13.129101 | 
2025-10-11 00:19:13.129380 | TASK [add-build-sshkey : Add back temp key]
2025-10-11 00:19:13.413514 | controller -> localhost | Identity added: /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/work/de7ebd89e446428ba4a8a4e5656b31a1_id_rsa (zuul-build-sshkey)
2025-10-11 00:19:13.413776 | controller -> localhost | ok: Runtime: 0:00:00.008368
2025-10-11 00:19:13.419817 | 
2025-10-11 00:19:13.419878 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-11 00:19:13.921169 | controller | ok
2025-10-11 00:19:13.933804 | 
2025-10-11 00:19:13.933947 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-11 00:19:13.974951 | controller | skipping: Conditional result was False
2025-10-11 00:19:14.003718 | 
2025-10-11 00:19:14.003913 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-11 00:19:14.042596 | controller | ok
2025-10-11 00:19:14.070286 | 
2025-10-11 00:19:14.070430 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-11 00:19:14.353567 | controller -> localhost | ok
2025-10-11 00:19:14.390396 | 
2025-10-11 00:19:14.390597 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-11 00:19:14.429014 | controller | ok
2025-10-11 00:19:14.447319 | controller | included: /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-11 00:19:14.456490 | 
2025-10-11 00:19:14.456577 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-11 00:19:14.756317 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-11 00:19:14.756580 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/work/de7ebd89e446428ba4a8a4e5656b31a1_id_ecdsa.
2025-10-11 00:19:14.756609 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/work/de7ebd89e446428ba4a8a4e5656b31a1_id_ecdsa.pub.
2025-10-11 00:19:14.756640 | controller -> localhost | The key fingerprint is:
2025-10-11 00:19:14.756660 | controller -> localhost | SHA256:cMbFXk2yZ2Puy2gcvD9ZsETN34YvJ/Q3DN3FB8/SXP8 zuul-build-sshkey
2025-10-11 00:19:14.756699 | controller -> localhost | The key's randomart image is:
2025-10-11 00:19:14.756724 | controller -> localhost | +---[ECDSA 521]---+
2025-10-11 00:19:14.756744 | controller -> localhost | |         .. .oo=.|
2025-10-11 00:19:14.756762 | controller -> localhost | |       . .. .oo=O|
2025-10-11 00:19:14.756780 | controller -> localhost | |      . +. ...B.%|
2025-10-11 00:19:14.756797 | controller -> localhost | |       +  .  *=+*|
2025-10-11 00:19:14.756815 | controller -> localhost | |        S  . o+*E|
2025-10-11 00:19:14.756833 | controller -> localhost | |            o.+o*|
2025-10-11 00:19:14.756851 | controller -> localhost | |           . o.*o|
2025-10-11 00:19:14.756868 | controller -> localhost | |            +oo. |
2025-10-11 00:19:14.756885 | controller -> localhost | |           ...+. |
2025-10-11 00:19:14.756903 | controller -> localhost | +----[SHA256]-----+
2025-10-11 00:19:14.756957 | controller -> localhost | ok: Runtime: 0:00:00.010979
2025-10-11 00:19:14.764084 | 
2025-10-11 00:19:14.764153 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-11 00:19:14.795516 | controller | ok
2025-10-11 00:19:14.816026 | controller | included: /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-11 00:19:14.830142 | 
2025-10-11 00:19:14.830253 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-11 00:19:14.856769 | controller | skipping: Conditional result was False
2025-10-11 00:19:14.868304 | 
2025-10-11 00:19:14.868487 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-11 00:19:15.379642 | controller | changed
2025-10-11 00:19:15.395519 | 
2025-10-11 00:19:15.395838 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-11 00:19:15.777497 | controller | ok
2025-10-11 00:19:15.803003 | 
2025-10-11 00:19:15.803133 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-11 00:19:17.113116 | controller | changed
2025-10-11 00:19:17.129668 | 
2025-10-11 00:19:17.129890 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-11 00:19:18.442843 | controller | changed
2025-10-11 00:19:18.457461 | 
2025-10-11 00:19:18.457631 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-11 00:19:18.485982 | controller | skipping: Conditional result was False
2025-10-11 00:19:18.502536 | 
2025-10-11 00:19:18.502746 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-11 00:19:18.805495 | controller -> localhost | changed
2025-10-11 00:19:18.837769 | 
2025-10-11 00:19:18.838002 | TASK [add-build-sshkey : Add back temp key]
2025-10-11 00:19:19.165370 | controller -> localhost | Identity added: /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/work/de7ebd89e446428ba4a8a4e5656b31a1_id_ecdsa (zuul-build-sshkey)
2025-10-11 00:19:19.165593 | controller -> localhost | ok: Runtime: 0:00:00.007664
2025-10-11 00:19:19.172649 | 
2025-10-11 00:19:19.172740 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-11 00:19:19.516619 | controller | ok
2025-10-11 00:19:19.527455 | 
2025-10-11 00:19:19.527612 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-11 00:19:19.565354 | controller | skipping: Conditional result was False
2025-10-11 00:19:19.642790 | 
2025-10-11 00:19:19.642956 | TASK [include_role : remove-zuul-sshkey]
2025-10-11 00:19:19.670088 | controller | skipping: Conditional result was False
2025-10-11 00:19:19.678309 | 
2025-10-11 00:19:19.678423 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-11 00:19:20.013496 | controller | ok: "logs"
2025-10-11 00:19:20.014477 | controller | ok: All items complete
2025-10-11 00:19:20.014559 | 
2025-10-11 00:19:20.308916 | controller | ok: "artifacts"
2025-10-11 00:19:20.602091 | controller | ok: "docs"
2025-10-11 00:19:20.626177 | 
2025-10-11 00:19:20.626346 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-11 00:19:20.987158 | controller | changed: "logs"
2025-10-11 00:19:21.284935 | controller | changed: "artifacts"
2025-10-11 00:19:21.566643 | controller | changed: "docs"
2025-10-11 00:19:21.599983 | 
2025-10-11 00:19:21.600119 | PLAY RECAP
2025-10-11 00:19:21.600163 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-11 00:19:21.600189 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-11 00:19:21.600206 | 
2025-10-11 00:19:21.732431 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-11 00:19:21.735125 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-11 00:19:22.385148 | 
2025-10-11 00:19:22.385285 | PLAY [all]
2025-10-11 00:19:22.406764 | 
2025-10-11 00:19:22.406863 | TASK [Install binary dependencies]
2025-10-11 00:19:22.487958 | controller | ok
2025-10-11 00:19:22.507692 | 
2025-10-11 00:19:22.507784 | TASK [bindep : Include find tasks]
2025-10-11 00:19:22.541744 | controller | ok
2025-10-11 00:19:22.552845 | controller | included: /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-11 00:19:22.562137 | 
2025-10-11 00:19:22.562230 | TASK [bindep : Look for bindep.txt]
2025-10-11 00:19:23.148546 | controller | ok
2025-10-11 00:19:23.162152 | 
2025-10-11 00:19:23.162315 | TASK [bindep : Define bindep_file fact]
2025-10-11 00:19:23.179359 | controller | skipping: Conditional result was False
2025-10-11 00:19:23.193985 | 
2025-10-11 00:19:23.194131 | TASK [bindep : Look for other-requirements.txt]
2025-10-11 00:19:23.501337 | controller | ok
2025-10-11 00:19:23.506897 | 
2025-10-11 00:19:23.506974 | TASK [bindep : Define bindep_file fact]
2025-10-11 00:19:23.541380 | controller | skipping: Conditional result was False
2025-10-11 00:19:23.548286 | 
2025-10-11 00:19:23.548401 | TASK [bindep : Look for bindep fallback file]
2025-10-11 00:19:23.573648 | controller | skipping: Conditional result was False
2025-10-11 00:19:23.580429 | 
2025-10-11 00:19:23.580532 | TASK [bindep : Define bindep_file fact]
2025-10-11 00:19:23.605034 | controller | skipping: Conditional result was False
2025-10-11 00:19:23.613915 | 
2025-10-11 00:19:23.614027 | TASK [bindep : Include bindep tasks]
2025-10-11 00:19:23.639503 | controller | skipping: Conditional result was False
2025-10-11 00:19:23.647808 | 
2025-10-11 00:19:23.647918 | TASK [bindep : Include install tasks]
2025-10-11 00:19:23.675025 | controller | skipping: Conditional result was False
2025-10-11 00:19:23.682813 | 
2025-10-11 00:19:23.682918 | LOOP [bindep : Include package tasks]
2025-10-11 00:19:23.740768 | 
2025-10-11 00:19:23.740996 | TASK [Run test-setup role]
2025-10-11 00:19:23.764046 | controller | ok
2025-10-11 00:19:23.785785 | 
2025-10-11 00:19:23.785934 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-11 00:19:24.107470 | controller | ok
2025-10-11 00:19:24.113281 | 
2025-10-11 00:19:24.113351 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-11 00:19:24.256614 | controller | skipping: Conditional result was False
2025-10-11 00:19:24.306491 | 
2025-10-11 00:19:24.306626 | PLAY RECAP
2025-10-11 00:19:24.306701 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-11 00:19:24.306736 | 
2025-10-11 00:19:24.436318 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-11 00:19:24.438536 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-11 00:19:25.096520 | 
2025-10-11 00:19:25.096666 | PLAY [controller]
2025-10-11 00:19:25.116977 | 
2025-10-11 00:19:25.117084 | TASK [Create the /root directory]
2025-10-11 00:19:25.914180 | controller | ok
2025-10-11 00:19:25.933487 | 
2025-10-11 00:19:25.933869 | TASK [Install glibc-langpack-en]
2025-10-11 00:19:34.015753 | controller | ok: Nothing to do
2025-10-11 00:19:34.028535 | 
2025-10-11 00:19:34.028761 | TASK [Ensure controller directory exists]
2025-10-11 00:19:34.487187 | controller | changed
2025-10-11 00:19:34.500050 | 
2025-10-11 00:19:34.500192 | TASK [Install container runtime]
2025-10-11 00:19:34.571871 | controller | ok
2025-10-11 00:19:34.623266 | 
2025-10-11 00:19:34.623352 | LOOP [ensure-podman : Find distribution installation]
2025-10-11 00:19:34.678391 | controller | ok: "/var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-11 00:19:34.693468 | controller | included: /var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-11 00:19:34.708397 | 
2025-10-11 00:19:34.708491 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-11 00:20:52.166524 | controller | changed
2025-10-11 00:20:52.180216 | 
2025-10-11 00:20:52.180361 | TASK [ensure-podman : Fetch podman version]
2025-10-11 00:20:52.871130 | controller | Client:       Podman Engine
2025-10-11 00:20:52.900601 | controller | Version:      4.6.2
2025-10-11 00:20:52.900644 | controller | API Version:  4.6.2
2025-10-11 00:20:52.900651 | controller | Go Version:   go1.19.12
2025-10-11 00:20:52.900668 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-11 00:20:52.900675 | controller | OS/Arch:      linux/amd64
2025-10-11 00:20:53.330172 | controller | ok: Runtime: 0:00:00.224828
2025-10-11 00:20:53.343324 | 
2025-10-11 00:20:53.343485 | TASK [ensure-podman : Print podman version installed]
2025-10-11 00:20:53.380924 | Podman version: Client:       Podman Engine
2025-10-11 00:20:53.381185 | Version:      4.6.2
2025-10-11 00:20:53.381246 | API Version:  4.6.2
2025-10-11 00:20:53.381288 | Go Version:   go1.19.12
2025-10-11 00:20:53.381325 | Built:        Mon Aug 28 19:38:31 2023
2025-10-11 00:20:53.381361 | OS/Arch:      linux/amd64
2025-10-11 00:20:53.390640 | 
2025-10-11 00:20:53.390793 | TASK [ensure-podman : Validate podman engine]
2025-10-11 00:20:53.534567 | controller | skipping: Conditional result was False
2025-10-11 00:20:53.548236 | 
2025-10-11 00:20:53.548378 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-11 00:20:53.575861 | controller | skipping: Conditional result was False
2025-10-11 00:20:53.599522 | 
2025-10-11 00:20:53.599656 | TASK [Ensure python3.8 is present]
2025-10-11 00:20:53.616338 | controller | skipping: Conditional result was False
2025-10-11 00:20:53.629623 | 
2025-10-11 00:20:53.629813 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-11 00:20:53.659196 | controller | ok
2025-10-11 00:20:53.695043 | 
2025-10-11 00:20:53.695224 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-11 00:20:57.392241 | controller | ok: Nothing to do
2025-10-11 00:20:57.426046 | 
2025-10-11 00:20:57.426198 | TASK [our-ensure-python : Also install python3-devel]
2025-10-11 00:21:11.007845 | controller | changed
2025-10-11 00:21:11.027731 | 
2025-10-11 00:21:11.027862 | TASK [Run ensure-virtualenv role]
2025-10-11 00:21:11.050834 | controller | ok
2025-10-11 00:21:11.083420 | 
2025-10-11 00:21:11.083587 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-11 00:21:11.496355 | controller | /usr/bin/virtualenv
2025-10-11 00:21:11.737938 | controller | ok: Runtime: 0:00:00.004567
2025-10-11 00:21:11.752511 | 
2025-10-11 00:21:11.752665 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-11 00:21:11.792268 | controller | skipping: Conditional result was False
2025-10-11 00:21:11.792855 | controller | ok: All items complete
2025-10-11 00:21:11.792937 | 
2025-10-11 00:21:11.863785 | 
2025-10-11 00:21:11.863994 | TASK [Find the full path of the Python interpreter]
2025-10-11 00:21:12.323886 | controller | /usr/bin/python3
2025-10-11 00:21:12.506360 | controller | ok
2025-10-11 00:21:12.519890 | 
2025-10-11 00:21:12.520033 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-11 00:21:14.028565 | controller | created virtual environment CPython3.11.0.final.0-64 in 786ms
2025-10-11 00:21:14.069198 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-11 00:21:14.069258 | 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-11 00:21:14.069276 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-11 00:21:14.069300 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-11 00:21:14.186044 | controller | changed
2025-10-11 00:21:14.199771 | 
2025-10-11 00:21:14.199914 | TASK [Set selinux package]
2025-10-11 00:21:14.240831 | controller | ok
2025-10-11 00:21:14.254044 | 
2025-10-11 00:21:14.254208 | TASK [Set selinux package (Fedora)]
2025-10-11 00:21:14.287650 | controller | ok
2025-10-11 00:21:14.292773 | 
2025-10-11 00:21:14.292837 | TASK [Install selinux into virtualenv]
2025-10-11 00:21:16.932953 | controller | Collecting selinux-please-lie-to-me
2025-10-11 00:21:17.027753 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-11 00:21:17.557983 | controller | Collecting setuptools<50.0.0
2025-10-11 00:21:17.572339 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-11 00:21:17.700829 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.5 MB/s eta 0:00:00
2025-10-11 00:21:17.852504 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-11 00:21:17.852813 | controller |   Attempting uninstall: setuptools
2025-10-11 00:21:17.857862 | controller |     Found existing installation: setuptools 62.6.0
2025-10-11 00:21:17.970143 | controller |     Uninstalling setuptools-62.6.0:
2025-10-11 00:21:17.984880 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-11 00:21:18.726020 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-11 00:21:18.941215 | controller |
2025-10-11 00:21:19.154820 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-11 00:21:19.154865 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-11 00:21:19.489194 | controller | ok: Runtime: 0:00:04.389251
2025-10-11 00:21:19.498427 | 
2025-10-11 00:21:19.498533 | TASK [Install pytest-forked into virtualenv]
2025-10-11 00:21:20.729026 | controller | Collecting pytest-forked
2025-10-11 00:21:20.815249 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-11 00:21:20.874562 | controller | Collecting py
2025-10-11 00:21:20.886896 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-11 00:21:20.922396 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-10-11 00:21:21.092616 | controller | Collecting pytest>=3.10
2025-10-11 00:21:21.107691 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-11 00:21:21.167261 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00
2025-10-11 00:21:21.223059 | controller | Collecting iniconfig>=1
2025-10-11 00:21:21.235256 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-11 00:21:21.302926 | controller | Collecting packaging>=20
2025-10-11 00:21:21.319544 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-11 00:21:21.338236 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 3.8 MB/s eta 0:00:00
2025-10-11 00:21:21.383730 | controller | Collecting pluggy<2,>=1.5
2025-10-11 00:21:21.396219 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-11 00:21:21.465798 | controller | Collecting pygments>=2.7.2
2025-10-11 00:21:21.477817 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-11 00:21:21.596990 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.5 MB/s eta 0:00:00
2025-10-11 00:21:21.733648 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-11 00:21:23.982477 | 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-11 00:21:23.998630 | controller |
2025-10-11 00:21:24.187423 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-11 00:21:24.187475 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-11 00:21:24.687743 | controller | ok: Runtime: 0:00:04.216437
2025-10-11 00:21:24.696309 | 
2025-10-11 00:21:24.696424 | TASK [Update pip]
2025-10-11 00:21:25.823463 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-11 00:21:26.103167 | controller | Collecting pip
2025-10-11 00:21:26.200415 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-11 00:21:26.402408 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.0 MB/s eta 0:00:00
2025-10-11 00:21:26.567358 | controller | Installing collected packages: pip
2025-10-11 00:21:26.567652 | controller |   Attempting uninstall: pip
2025-10-11 00:21:26.575083 | controller |     Found existing installation: pip 22.2.2
2025-10-11 00:21:26.902576 | controller |     Uninstalling pip-22.2.2:
2025-10-11 00:21:26.941138 | controller |       Successfully uninstalled pip-22.2.2
2025-10-11 00:21:28.746415 | controller | Successfully installed pip-25.2
2025-10-11 00:21:29.350950 | controller | ok: Runtime: 0:00:03.712168
2025-10-11 00:21:29.363766 | 
2025-10-11 00:21:29.363898 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-11 00:21:29.918849 | controller | changed
2025-10-11 00:21:29.927250 | 
2025-10-11 00:21:29.927411 | TASK [Install ansible into virtualenv]
2025-10-11 00:21:30.989132 | controller | Processing ./src/github.com/ansible/ansible
2025-10-11 00:21:30.995594 | controller |   Installing build dependencies: started
2025-10-11 00:21:32.932831 | controller |   Installing build dependencies: finished with status 'done'
2025-10-11 00:21:34.455834 | controller |   Getting requirements to build wheel: started
2025-10-11 00:21:34.455904 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-11 00:21:34.457474 | controller |   Preparing metadata (pyproject.toml): started
2025-10-11 00:21:35.389853 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-11 00:21:35.393165 | 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-11 00:21:35.398060 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-11 00:21:36.059126 | controller | ERROR
2025-10-11 00:21:36.059454 | controller | {
2025-10-11 00:21:36.059522 | controller |   "delta": "0:00:05.193617",
2025-10-11 00:21:36.059568 | controller |   "end": "2025-10-11 00:21:35.554235",
2025-10-11 00:21:36.059611 | controller |   "msg": "non-zero return code",
2025-10-11 00:21:36.059675 | controller |   "rc": 1,
2025-10-11 00:21:36.059794 | controller |   "start": "2025-10-11 00:21:30.360618"
2025-10-11 00:21:36.059840 | controller | }
failure
2025-10-11 00:21:36.063876 | 
2025-10-11 00:21:36.064019 | PLAY RECAP
2025-10-11 00:21:36.064112 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-11 00:21:36.064158 | 
2025-10-11 00:21:36.204255 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-11 00:21:36.206172 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-11 00:21:36.827750 | 
2025-10-11 00:21:36.827895 | PLAY [all]
2025-10-11 00:21:36.851507 | 
2025-10-11 00:21:36.851710 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-11 00:21:37.648313 | controller | changed: non-zero return code
2025-10-11 00:21:37.661387 | 
2025-10-11 00:21:37.661568 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-11 00:21:37.689912 | controller | skipping: Conditional result was False
2025-10-11 00:21:37.703129 | 
2025-10-11 00:21:37.703288 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-11 00:21:37.745970 | 
2025-10-11 00:21:37.746276 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-11 00:21:37.787161 | 
2025-10-11 00:21:37.787445 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-11 00:21:37.804659 | controller | skipping: Conditional result was False
2025-10-11 00:21:37.819319 | 
2025-10-11 00:21:37.819541 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-11 00:21:37.861934 | 
2025-10-11 00:21:37.862198 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-11 00:21:37.880662 | controller | skipping: Conditional result was False
2025-10-11 00:21:37.895080 | 
2025-10-11 00:21:37.895271 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-11 00:21:37.914161 | controller | skipping: Conditional result was False
2025-10-11 00:21:37.927727 | 
2025-10-11 00:21:37.927915 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-11 00:21:37.955661 | controller | skipping: Conditional result was False
2025-10-11 00:21:38.002382 | 
2025-10-11 00:21:38.002456 | PLAY RECAP
2025-10-11 00:21:38.002508 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-11 00:21:38.002536 | 
2025-10-11 00:21:38.109794 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-11 00:21:38.110696 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-11 00:21:38.680779 | 
2025-10-11 00:21:38.680907 | PLAY [all:!appliance*]
2025-10-11 00:21:38.701785 | 
2025-10-11 00:21:38.701897 | TASK [unregister the node]
2025-10-11 00:21:38.840123 | controller | skipping: Conditional result was False
2025-10-11 00:21:38.852657 | 
2025-10-11 00:21:38.852845 | TASK [include_role : fetch-output]
2025-10-11 00:21:38.906343 | controller | ok
2025-10-11 00:21:38.942718 | 
2025-10-11 00:21:38.942847 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-11 00:21:38.999748 | controller | skipping: Conditional result was False
2025-10-11 00:21:39.008901 | 
2025-10-11 00:21:39.009002 | TASK [fetch-output : Set log path for single node]
2025-10-11 00:21:39.050147 | controller | ok
2025-10-11 00:21:39.055636 | 
2025-10-11 00:21:39.055720 | LOOP [fetch-output : Ensure local output dirs]
2025-10-11 00:21:39.460309 | controller -> localhost | ok: "/var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/work/logs"
2025-10-11 00:21:39.692029 | controller -> localhost | changed: "/var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/work/artifacts"
2025-10-11 00:21:39.922875 | controller -> localhost | changed: "/var/lib/zuul/builds/de7ebd89e446428ba4a8a4e5656b31a1/work/docs"
2025-10-11 00:21:39.950178 | 
2025-10-11 00:21:39.950386 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-11 00:21:41.189407 | controller | changed:
2025-10-11 00:21:41.189797 | controller | .d..t...... ./
2025-10-11 00:21:41.189862 | controller | cd+++++++++ controller/
2025-10-11 00:21:41.189933 | controller | changed: All items complete
2025-10-11 00:21:41.189977 | 
2025-10-11 00:21:42.257121 | controller | changed: .d..t...... ./
2025-10-11 00:21:43.326566 | controller | changed: .d..t...... ./
2025-10-11 00:21:43.356913 | 
2025-10-11 00:21:43.357057 | TASK [include_role : fetch-output-openshift]
2025-10-11 00:21:43.383924 | controller | skipping: Conditional result was False
2025-10-11 00:21:43.393674 | 
2025-10-11 00:21:43.393797 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-11 00:21:43.437870 | controller | skipping: Conditional result was False
2025-10-11 00:21:43.448601 | controller | skipping: Conditional result was False
2025-10-11 00:21:43.477000 | 
2025-10-11 00:21:43.477121 | PLAY [localhost]
2025-10-11 00:21:43.489492 | 
2025-10-11 00:21:43.489557 | TASK [Run Zuul manifest role]
2025-10-11 00:21:43.507088 | localhost | ok
2025-10-11 00:21:43.519811 | 
2025-10-11 00:21:43.519875 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-11 00:21:43.946262 | localhost | changed
2025-10-11 00:21:43.950775 | 
2025-10-11 00:21:43.950838 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-11 00:21:43.991531 | localhost | ok
2025-10-11 00:21:44.000159 | 
2025-10-11 00:21:44.000221 | TASK [Set zuul-log-path fact]
2025-10-11 00:21:44.020337 | localhost | ok
2025-10-11 00:21:44.034176 | 
2025-10-11 00:21:44.034244 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-11 00:21:44.073982 | localhost | ok
2025-10-11 00:21:44.083927 | 
2025-10-11 00:21:44.083988 | LOOP [Run upload-logs-swift role]
2025-10-11 00:21:44.131499 | localhost | Output suppressed because no_log was given
2025-10-11 00:21:44.159270 | 
2025-10-11 00:21:44.159340 | TASK [Set zuul-log-path fact]
2025-10-11 00:21:44.194199 | localhost | skipping: Conditional result was False
2025-10-11 00:21:44.199890 | 
2025-10-11 00:21:44.199956 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-11 00:21:44.671985 | localhost -> localhost | ok: Runtime: 0:00:00.009013
2025-10-11 00:21:44.683821 | 
2025-10-11 00:21:44.683969 | TASK [upload-logs-swift : Upload logs to swift]