2025-10-12 00:12:33.547416 | Job console starting...
2025-10-12 00:12:33.560342 | Updating repositories
2025-10-12 00:12:33.663964 | Preparing job workspace
2025-10-12 00:12:37.249722 | Running Ansible setup...
2025-10-12 00:12:45.774900 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-12 00:12:46.464719 | 
2025-10-12 00:12:46.464851 | PLAY [localhost]
2025-10-12 00:12:46.473647 | 
2025-10-12 00:12:46.473722 | TASK [Gathering Facts]
2025-10-12 00:12:47.751568 | localhost | ok
2025-10-12 00:12:47.779459 | 
2025-10-12 00:12:47.779709 | TASK [Setup log path fact]
2025-10-12 00:12:47.815219 | localhost | ok
2025-10-12 00:12:47.837687 | 
2025-10-12 00:12:47.837928 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-12 00:12:47.874191 | localhost | ok
2025-10-12 00:12:47.886796 | 
2025-10-12 00:12:47.886994 | TASK [emit-job-header : Print job information]
2025-10-12 00:12:47.928670 | # Job Information
2025-10-12 00:12:47.928935 | Ansible Version: 2.15.12
2025-10-12 00:12:47.928974 | Job: ansible-test-sanity-docker-milestone
2025-10-12 00:12:47.928996 | Pipeline: periodic
2025-10-12 00:12:47.929027 | Executor: ze01.softwarefactory-project.io
2025-10-12 00:12:47.929050 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-12 00:12:47.929072 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/bd0/ansible/bd0f8ee55a6c4d42856ccff68e99b536/
2025-10-12 00:12:47.929091 | Event ID: 6345c3b581e843d6946dd6bca9ffe8f8
2025-10-12 00:12:47.934426 | 
2025-10-12 00:12:47.934619 | LOOP [emit-job-header : Print node information]
2025-10-12 00:12:48.053694 | localhost | ok:
2025-10-12 00:12:48.053903 | localhost | # Node Information
2025-10-12 00:12:48.053930 | localhost | Inventory Hostname: controller
2025-10-12 00:12:48.053949 | localhost | Hostname: np0005481421
2025-10-12 00:12:48.053968 | localhost | Username: zuul
2025-10-12 00:12:48.053992 | localhost | Distro: Fedora 37
2025-10-12 00:12:48.054011 | localhost | Provider: ansible-vexxhost-ams1
2025-10-12 00:12:48.054091 | localhost | Region: ams1
2025-10-12 00:12:48.054110 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-12 00:12:48.054127 | localhost | Product Name: OpenStack Nova
2025-10-12 00:12:48.054145 | localhost | Interface IP: 38.129.16.40
2025-10-12 00:12:48.070860 | 
2025-10-12 00:12:48.070993 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-12 00:12:48.433601 | localhost -> localhost | changed
2025-10-12 00:12:48.443522 | 
2025-10-12 00:12:48.443686 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-12 00:12:49.322749 | localhost -> localhost | changed
2025-10-12 00:12:49.343881 | 
2025-10-12 00:12:49.343961 | PLAY [all:!appliance*]
2025-10-12 00:12:49.360962 | 
2025-10-12 00:12:49.361095 | TASK [include_role : start-zuul-console]
2025-10-12 00:12:49.382306 | controller | ok
2025-10-12 00:12:49.396745 | 
2025-10-12 00:12:49.396886 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-12 00:12:50.623042 | controller | ok
2025-10-12 00:12:50.637428 | 
2025-10-12 00:12:50.637534 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-12 00:12:53.538655 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-12 00:12:53.549338 | 
2025-10-12 00:12:53.549504 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-12 00:12:53.918489 | controller | skipping: Conditional result was False
2025-10-12 00:12:53.925684 | 
2025-10-12 00:12:53.925770 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-12 00:12:53.950047 | controller | skipping: Conditional result was False
2025-10-12 00:12:53.956188 | 
2025-10-12 00:12:53.956261 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-12 00:12:53.980212 | controller | skipping: Conditional result was False
2025-10-12 00:12:53.986796 | 
2025-10-12 00:12:53.986871 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-12 00:12:54.013546 | controller | skipping: Conditional result was False
2025-10-12 00:12:54.023910 | 
2025-10-12 00:12:54.024074 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-12 00:12:54.054366 | controller | skipping: Conditional result was False
2025-10-12 00:12:54.060750 | 
2025-10-12 00:12:54.060910 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-12 00:12:54.074884 | controller | skipping: Conditional result was False
2025-10-12 00:12:54.088881 | 
2025-10-12 00:12:54.089005 | TASK [Disable Fedora Modular]
2025-10-12 00:12:55.465588 | controller | changed
2025-10-12 00:12:55.479290 | 
2025-10-12 00:12:55.479426 | TASK [Enable EPEL]
2025-10-12 00:12:55.506715 | controller | skipping: Conditional result was False
2025-10-12 00:12:55.521655 | 
2025-10-12 00:12:55.521806 | TASK [Register the RHEL node]
2025-10-12 00:12:55.941156 | 
2025-10-12 00:12:55.941309 | TASK [Show the subscription-manager status]
2025-10-12 00:12:56.299639 | controller | skipping: Conditional result was False
2025-10-12 00:12:56.306381 | 
2025-10-12 00:12:56.306459 | TASK [Enable EPEL on RHEL]
2025-10-12 00:12:56.680086 | controller | skipping: Conditional result was False
2025-10-12 00:12:56.686750 | 
2025-10-12 00:12:56.686841 | TASK [Install git and tox]
2025-10-12 00:15:38.622278 | controller | changed
2025-10-12 00:15:38.632616 | 
2025-10-12 00:15:38.632748 | TASK [include_role : prepare-workspace]
2025-10-12 00:15:38.666537 | controller | ok
2025-10-12 00:15:38.694918 | 
2025-10-12 00:15:38.695066 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-12 00:15:39.604285 | controller | ok
2025-10-12 00:15:39.613063 | 
2025-10-12 00:15:39.613184 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-12 00:15:56.624216 | controller | Output suppressed because no_log was given
2025-10-12 00:15:56.702393 | 
2025-10-12 00:15:56.702744 | TASK [include_role : prepare-workspace-openshift]
2025-10-12 00:15:56.730586 | controller | skipping: Conditional result was False
2025-10-12 00:15:56.763431 | 
2025-10-12 00:15:56.763553 | PLAY [all:!appliance]
2025-10-12 00:15:56.789455 | 
2025-10-12 00:15:56.789612 | TASK [Run add-build-sshkey role (RSA)]
2025-10-12 00:15:56.826034 | controller | ok
2025-10-12 00:15:56.850403 | 
2025-10-12 00:15:56.850530 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-12 00:15:57.153800 | controller -> localhost | ok
2025-10-12 00:15:57.162498 | 
2025-10-12 00:15:57.162600 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-12 00:15:57.195952 | controller | ok
2025-10-12 00:15:57.216148 | controller | included: /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-12 00:15:57.225912 | 
2025-10-12 00:15:57.226052 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-12 00:15:57.687682 | controller -> localhost | Generating public/private rsa key pair.
2025-10-12 00:15:57.687999 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/work/bd0f8ee55a6c4d42856ccff68e99b536_id_rsa.
2025-10-12 00:15:57.688073 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/work/bd0f8ee55a6c4d42856ccff68e99b536_id_rsa.pub.
2025-10-12 00:15:57.688109 | controller -> localhost | The key fingerprint is:
2025-10-12 00:15:57.688131 | controller -> localhost | SHA256:/5YdFmUdxkN3Cyb2chYQDOjLl8SMLF3HkaQd8BboQH4 zuul-build-sshkey
2025-10-12 00:15:57.688150 | controller -> localhost | The key's randomart image is:
2025-10-12 00:15:57.688168 | controller -> localhost | +---[RSA 2048]----+
2025-10-12 00:15:57.688186 | controller -> localhost | |      ...oBX=+o+=|
2025-10-12 00:15:57.688204 | controller -> localhost | |      .o o==* +oB|
2025-10-12 00:15:57.688221 | controller -> localhost | |      +.BE.= + +.|
2025-10-12 00:15:57.688238 | controller -> localhost | |     . =.=. + .  |
2025-10-12 00:15:57.688269 | controller -> localhost | |      o S .    . |
2025-10-12 00:15:57.688315 | controller -> localhost | |       o +    o  |
2025-10-12 00:15:57.688358 | controller -> localhost | |        . .  + . |
2025-10-12 00:15:57.688389 | controller -> localhost | |           .o .  |
2025-10-12 00:15:57.688417 | controller -> localhost | |           ..    |
2025-10-12 00:15:57.688463 | controller -> localhost | +----[SHA256]-----+
2025-10-12 00:15:57.688520 | controller -> localhost | ok: Runtime: 0:00:00.047712
2025-10-12 00:15:57.698792 | 
2025-10-12 00:15:57.698889 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-12 00:15:57.739275 | controller | ok
2025-10-12 00:15:57.756088 | controller | included: /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-12 00:15:57.771046 | 
2025-10-12 00:15:57.771245 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-12 00:15:57.809324 | controller | skipping: Conditional result was False
2025-10-12 00:15:57.821268 | 
2025-10-12 00:15:57.821808 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-12 00:15:59.060089 | controller | changed
2025-10-12 00:15:59.068698 | 
2025-10-12 00:15:59.068801 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-12 00:15:59.735408 | controller | ok
2025-10-12 00:15:59.752802 | 
2025-10-12 00:15:59.753329 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-12 00:16:03.037380 | controller | changed
2025-10-12 00:16:03.060004 | 
2025-10-12 00:16:03.060176 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-12 00:16:06.264140 | controller | changed
2025-10-12 00:16:06.274232 | 
2025-10-12 00:16:06.274397 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-12 00:16:06.300287 | controller | skipping: Conditional result was False
2025-10-12 00:16:06.309727 | 
2025-10-12 00:16:06.309845 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-12 00:16:06.746505 | controller -> localhost | changed
2025-10-12 00:16:06.759163 | 
2025-10-12 00:16:06.759269 | TASK [add-build-sshkey : Add back temp key]
2025-10-12 00:16:07.060534 | controller -> localhost | Identity added: /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/work/bd0f8ee55a6c4d42856ccff68e99b536_id_rsa (zuul-build-sshkey)
2025-10-12 00:16:07.060835 | controller -> localhost | ok: Runtime: 0:00:00.008620
2025-10-12 00:16:07.069063 | 
2025-10-12 00:16:07.069377 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-12 00:16:08.132214 | controller | ok
2025-10-12 00:16:08.141736 | 
2025-10-12 00:16:08.141876 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-12 00:16:08.167873 | controller | skipping: Conditional result was False
2025-10-12 00:16:08.180376 | 
2025-10-12 00:16:08.180492 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-12 00:16:08.202889 | controller | ok
2025-10-12 00:16:08.221730 | 
2025-10-12 00:16:08.221875 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-12 00:16:08.462594 | controller -> localhost | ok
2025-10-12 00:16:08.474205 | 
2025-10-12 00:16:08.474391 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-12 00:16:08.509617 | controller | ok
2025-10-12 00:16:08.531291 | controller | included: /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-12 00:16:08.544428 | 
2025-10-12 00:16:08.544592 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-12 00:16:08.816838 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-12 00:16:08.817148 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/work/bd0f8ee55a6c4d42856ccff68e99b536_id_ecdsa.
2025-10-12 00:16:08.817190 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/work/bd0f8ee55a6c4d42856ccff68e99b536_id_ecdsa.pub.
2025-10-12 00:16:08.817228 | controller -> localhost | The key fingerprint is:
2025-10-12 00:16:08.817258 | controller -> localhost | SHA256:JUL9HUrH517Di3WN7xlzoW1Ma3kTDCTDJwZSKhGZkeY zuul-build-sshkey
2025-10-12 00:16:08.817286 | controller -> localhost | The key's randomart image is:
2025-10-12 00:16:08.817313 | controller -> localhost | +---[ECDSA 521]---+
2025-10-12 00:16:08.817340 | controller -> localhost | |     +Bo.oo+..   |
2025-10-12 00:16:08.817366 | controller -> localhost | |     *. + .+*o.  |
2025-10-12 00:16:08.817399 | controller -> localhost | |    o....oo+o++..|
2025-10-12 00:16:08.817423 | controller -> localhost | |     E.. oo . oO+|
2025-10-12 00:16:08.817446 | controller -> localhost | |        S    .BoO|
2025-10-12 00:16:08.817469 | controller -> localhost | |             o.%+|
2025-10-12 00:16:08.817491 | controller -> localhost | |              o.B|
2025-10-12 00:16:08.817512 | controller -> localhost | |               ..|
2025-10-12 00:16:08.817533 | controller -> localhost | |                 |
2025-10-12 00:16:08.817555 | controller -> localhost | +----[SHA256]-----+
2025-10-12 00:16:08.817619 | controller -> localhost | ok: Runtime: 0:00:00.008201
2025-10-12 00:16:08.826174 | 
2025-10-12 00:16:08.826270 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-12 00:16:08.848851 | controller | ok
2025-10-12 00:16:08.860744 | controller | included: /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-12 00:16:08.871151 | 
2025-10-12 00:16:08.871245 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-12 00:16:08.886709 | controller | skipping: Conditional result was False
2025-10-12 00:16:08.930244 | 
2025-10-12 00:16:08.930370 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-12 00:16:10.014155 | controller | changed
2025-10-12 00:16:10.022038 | 
2025-10-12 00:16:10.022175 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-12 00:16:10.788061 | controller | ok
2025-10-12 00:16:10.797751 | 
2025-10-12 00:16:10.797870 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-12 00:16:14.125485 | controller | changed
2025-10-12 00:16:14.142398 | 
2025-10-12 00:16:14.142522 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-12 00:16:17.344618 | controller | changed
2025-10-12 00:16:17.355797 | 
2025-10-12 00:16:17.355926 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-12 00:16:17.381393 | controller | skipping: Conditional result was False
2025-10-12 00:16:17.391584 | 
2025-10-12 00:16:17.391697 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-12 00:16:17.632041 | controller -> localhost | changed
2025-10-12 00:16:17.648359 | 
2025-10-12 00:16:17.648498 | TASK [add-build-sshkey : Add back temp key]
2025-10-12 00:16:17.952877 | controller -> localhost | Identity added: /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/work/bd0f8ee55a6c4d42856ccff68e99b536_id_ecdsa (zuul-build-sshkey)
2025-10-12 00:16:17.953106 | controller -> localhost | ok: Runtime: 0:00:00.008197
2025-10-12 00:16:17.966350 | 
2025-10-12 00:16:17.966508 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-12 00:16:18.796411 | controller | ok
2025-10-12 00:16:18.802823 | 
2025-10-12 00:16:18.802911 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-12 00:16:18.832356 | controller | skipping: Conditional result was False
2025-10-12 00:16:18.846718 | 
2025-10-12 00:16:18.846846 | TASK [include_role : remove-zuul-sshkey]
2025-10-12 00:16:18.862167 | controller | skipping: Conditional result was False
2025-10-12 00:16:18.869157 | 
2025-10-12 00:16:18.869259 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-12 00:16:19.606615 | controller | ok: "logs"
2025-10-12 00:16:19.606979 | controller | ok: All items complete
2025-10-12 00:16:19.607059 | 
2025-10-12 00:16:20.333934 | controller | ok: "artifacts"
2025-10-12 00:16:21.027319 | controller | ok: "docs"
2025-10-12 00:16:21.049002 | 
2025-10-12 00:16:21.049248 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-12 00:16:21.785634 | controller | changed: "logs"
2025-10-12 00:16:22.528090 | controller | changed: "artifacts"
2025-10-12 00:16:23.283646 | controller | changed: "docs"
2025-10-12 00:16:23.318354 | 
2025-10-12 00:16:23.318477 | PLAY RECAP
2025-10-12 00:16:23.318525 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-12 00:16:23.318551 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-12 00:16:23.318570 | 
2025-10-12 00:16:23.446563 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-12 00:16:23.447493 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-12 00:16:24.197694 | 
2025-10-12 00:16:24.197832 | PLAY [all]
2025-10-12 00:16:24.223281 | 
2025-10-12 00:16:24.223425 | TASK [Install binary dependencies]
2025-10-12 00:16:24.285888 | controller | ok
2025-10-12 00:16:24.312918 | 
2025-10-12 00:16:24.313085 | TASK [bindep : Include find tasks]
2025-10-12 00:16:24.343828 | controller | ok
2025-10-12 00:16:24.353310 | controller | included: /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-12 00:16:24.361171 | 
2025-10-12 00:16:24.361279 | TASK [bindep : Look for bindep.txt]
2025-10-12 00:16:25.326613 | controller | ok
2025-10-12 00:16:25.335390 | 
2025-10-12 00:16:25.335557 | TASK [bindep : Define bindep_file fact]
2025-10-12 00:16:25.352379 | controller | skipping: Conditional result was False
2025-10-12 00:16:25.362507 | 
2025-10-12 00:16:25.362646 | TASK [bindep : Look for other-requirements.txt]
2025-10-12 00:16:26.058649 | controller | ok
2025-10-12 00:16:26.075812 | 
2025-10-12 00:16:26.076103 | TASK [bindep : Define bindep_file fact]
2025-10-12 00:16:26.114601 | controller | skipping: Conditional result was False
2025-10-12 00:16:26.124458 | 
2025-10-12 00:16:26.124583 | TASK [bindep : Look for bindep fallback file]
2025-10-12 00:16:26.162577 | controller | skipping: Conditional result was False
2025-10-12 00:16:26.172273 | 
2025-10-12 00:16:26.172414 | TASK [bindep : Define bindep_file fact]
2025-10-12 00:16:26.199784 | controller | skipping: Conditional result was False
2025-10-12 00:16:26.209446 | 
2025-10-12 00:16:26.209571 | TASK [bindep : Include bindep tasks]
2025-10-12 00:16:26.245512 | controller | skipping: Conditional result was False
2025-10-12 00:16:26.254526 | 
2025-10-12 00:16:26.254671 | TASK [bindep : Include install tasks]
2025-10-12 00:16:26.281218 | controller | skipping: Conditional result was False
2025-10-12 00:16:26.288542 | 
2025-10-12 00:16:26.288678 | LOOP [bindep : Include package tasks]
2025-10-12 00:16:26.358959 | 
2025-10-12 00:16:26.359170 | TASK [Run test-setup role]
2025-10-12 00:16:26.382096 | controller | ok
2025-10-12 00:16:26.407756 | 
2025-10-12 00:16:26.407921 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-12 00:16:27.278216 | controller | ok
2025-10-12 00:16:27.286252 | 
2025-10-12 00:16:27.286392 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-12 00:16:27.650161 | controller | skipping: Conditional result was False
2025-10-12 00:16:27.706229 | 
2025-10-12 00:16:27.706356 | PLAY RECAP
2025-10-12 00:16:27.706413 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-12 00:16:27.706442 | 
2025-10-12 00:16:27.836183 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-12 00:16:27.837652 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-12 00:16:28.487615 | 
2025-10-12 00:16:28.487771 | PLAY [controller]
2025-10-12 00:16:28.508938 | 
2025-10-12 00:16:28.509075 | TASK [Create the /root directory]
2025-10-12 00:16:29.680950 | controller | ok
2025-10-12 00:16:29.690184 | 
2025-10-12 00:16:29.690356 | TASK [Install glibc-langpack-en]
2025-10-12 00:16:40.519078 | controller | ok: Nothing to do
2025-10-12 00:16:40.531193 | 
2025-10-12 00:16:40.531342 | TASK [Ensure controller directory exists]
2025-10-12 00:16:41.516094 | controller | changed
2025-10-12 00:16:41.529649 | 
2025-10-12 00:16:41.529824 | TASK [Install container runtime]
2025-10-12 00:16:41.611183 | controller | ok
2025-10-12 00:16:41.673462 | 
2025-10-12 00:16:41.673617 | LOOP [ensure-podman : Find distribution installation]
2025-10-12 00:16:41.697954 | controller | ok: "/var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-12 00:16:41.704923 | controller | included: /var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-12 00:16:41.711839 | 
2025-10-12 00:16:41.711918 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-12 00:19:08.520474 | controller | changed
2025-10-12 00:19:08.541792 | 
2025-10-12 00:19:08.541964 | TASK [ensure-podman : Fetch podman version]
2025-10-12 00:19:09.732429 | controller | Client:       Podman Engine
2025-10-12 00:19:09.775028 | controller | Version:      4.6.2
2025-10-12 00:19:09.775081 | controller | API Version:  4.6.2
2025-10-12 00:19:09.775089 | controller | Go Version:   go1.19.12
2025-10-12 00:19:09.775108 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-12 00:19:09.775116 | controller | OS/Arch:      linux/amd64
2025-10-12 00:19:09.907696 | controller | ok: Runtime: 0:00:00.309468
2025-10-12 00:19:09.916827 | 
2025-10-12 00:19:09.916929 | TASK [ensure-podman : Print podman version installed]
2025-10-12 00:19:09.948815 | Podman version: Client:       Podman Engine
2025-10-12 00:19:09.948964 | Version:      4.6.2
2025-10-12 00:19:09.948993 | API Version:  4.6.2
2025-10-12 00:19:09.949028 | Go Version:   go1.19.12
2025-10-12 00:19:09.949052 | Built:        Mon Aug 28 19:38:31 2023
2025-10-12 00:19:09.949091 | OS/Arch:      linux/amd64
2025-10-12 00:19:09.956744 | 
2025-10-12 00:19:09.956818 | TASK [ensure-podman : Validate podman engine]
2025-10-12 00:19:10.311242 | controller | skipping: Conditional result was False
2025-10-12 00:19:10.320669 | 
2025-10-12 00:19:10.320868 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-12 00:19:10.347671 | controller | skipping: Conditional result was False
2025-10-12 00:19:10.368403 | 
2025-10-12 00:19:10.368648 | TASK [Ensure python3.8 is present]
2025-10-12 00:19:10.398508 | controller | skipping: Conditional result was False
2025-10-12 00:19:10.410506 | 
2025-10-12 00:19:10.410734 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-12 00:19:10.438587 | controller | ok
2025-10-12 00:19:10.468736 | 
2025-10-12 00:19:10.468973 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-12 00:19:14.548867 | controller | ok: Nothing to do
2025-10-12 00:19:14.561260 | 
2025-10-12 00:19:14.561391 | TASK [our-ensure-python : Also install python3-devel]
2025-10-12 00:19:31.372152 | controller | changed
2025-10-12 00:19:31.398861 | 
2025-10-12 00:19:31.399058 | TASK [Run ensure-virtualenv role]
2025-10-12 00:19:31.423435 | controller | ok
2025-10-12 00:19:31.456776 | 
2025-10-12 00:19:31.456958 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-12 00:19:32.296454 | controller | /usr/bin/virtualenv
2025-10-12 00:19:32.852044 | controller | ok: Runtime: 0:00:00.008954
2025-10-12 00:19:32.865414 | 
2025-10-12 00:19:32.865553 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-12 00:19:32.893287 | controller | skipping: Conditional result was False
2025-10-12 00:19:32.893895 | controller | ok: All items complete
2025-10-12 00:19:32.893985 | 
2025-10-12 00:19:32.920251 | 
2025-10-12 00:19:32.920440 | TASK [Find the full path of the Python interpreter]
2025-10-12 00:19:33.908110 | controller | /usr/bin/python3
2025-10-12 00:19:34.291011 | controller | ok
2025-10-12 00:19:34.302963 | 
2025-10-12 00:19:34.303274 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-12 00:19:36.712712 | controller | created virtual environment CPython3.11.0.final.0-64 in 1123ms
2025-10-12 00:19:36.776850 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-12 00:19:36.776906 | 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/.local/share/virtualenv)
2025-10-12 00:19:36.776922 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-12 00:19:36.776942 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-12 00:19:37.183359 | controller | changed
2025-10-12 00:19:37.194226 | 
2025-10-12 00:19:37.194329 | TASK [Set selinux package]
2025-10-12 00:19:37.228992 | controller | ok
2025-10-12 00:19:37.237139 | 
2025-10-12 00:19:37.237228 | TASK [Set selinux package (Fedora)]
2025-10-12 00:19:37.283196 | controller | ok
2025-10-12 00:19:37.291065 | 
2025-10-12 00:19:37.291160 | TASK [Install selinux into virtualenv]
2025-10-12 00:19:41.124461 | controller | Collecting selinux-please-lie-to-me
2025-10-12 00:19:41.289885 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-12 00:19:41.921439 | controller | Collecting setuptools<50.0.0
2025-10-12 00:19:41.927963 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-12 00:19:42.000863 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 11.7 MB/s eta 0:00:00
2025-10-12 00:19:42.180408 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-12 00:19:42.180991 | controller |   Attempting uninstall: setuptools
2025-10-12 00:19:42.186541 | controller |     Found existing installation: setuptools 62.6.0
2025-10-12 00:19:42.314116 | controller |     Uninstalling setuptools-62.6.0:
2025-10-12 00:19:42.332766 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-12 00:19:43.300220 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-12 00:19:43.607094 | controller |
2025-10-12 00:19:44.081905 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-12 00:19:44.081964 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-12 00:19:44.239653 | controller | ok: Runtime: 0:00:05.912123
2025-10-12 00:19:44.249373 | 
2025-10-12 00:19:44.249551 | TASK [Install pytest-forked into virtualenv]
2025-10-12 00:19:45.973317 | controller | Collecting pytest-forked
2025-10-12 00:19:46.074453 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-12 00:19:46.161972 | controller | Collecting py
2025-10-12 00:19:46.171877 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-12 00:19:46.220498 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.1 MB/s eta 0:00:00
2025-10-12 00:19:46.446008 | controller | Collecting pytest>=3.10
2025-10-12 00:19:46.452150 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-12 00:19:46.482583 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 14.5 MB/s eta 0:00:00
2025-10-12 00:19:46.551401 | controller | Collecting iniconfig>=1
2025-10-12 00:19:46.561400 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-12 00:19:46.646732 | controller | Collecting packaging>=20
2025-10-12 00:19:46.650356 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-12 00:19:46.681449 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 2.3 MB/s eta 0:00:00
2025-10-12 00:19:46.769093 | controller | Collecting pluggy<2,>=1.5
2025-10-12 00:19:46.784722 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-12 00:19:46.892181 | controller | Collecting pygments>=2.7.2
2025-10-12 00:19:46.905083 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-12 00:19:46.948903 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 32.6 MB/s eta 0:00:00
2025-10-12 00:19:47.103631 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-12 00:19:50.077599 | 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-12 00:19:50.109134 | controller |
2025-10-12 00:19:50.466467 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-12 00:19:50.466512 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-12 00:19:50.636096 | controller | ok: Runtime: 0:00:05.359712
2025-10-12 00:19:50.650205 | 
2025-10-12 00:19:50.650392 | TASK [Update pip]
2025-10-12 00:19:52.253558 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-12 00:19:52.589820 | controller | Collecting pip
2025-10-12 00:19:52.677041 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-12 00:19:52.768461 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 21.0 MB/s eta 0:00:00
2025-10-12 00:19:52.904895 | controller | Installing collected packages: pip
2025-10-12 00:19:52.905216 | controller |   Attempting uninstall: pip
2025-10-12 00:19:52.910546 | controller |     Found existing installation: pip 22.2.2
2025-10-12 00:19:53.221403 | controller |     Uninstalling pip-22.2.2:
2025-10-12 00:19:53.252574 | controller |       Successfully uninstalled pip-22.2.2
2025-10-12 00:19:55.387073 | controller | Successfully installed pip-25.2
2025-10-12 00:19:56.036267 | controller | ok: Runtime: 0:00:04.099819
2025-10-12 00:19:56.044975 | 
2025-10-12 00:19:56.045223 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-12 00:19:56.993303 | controller | changed
2025-10-12 00:19:57.006620 | 
2025-10-12 00:19:57.006789 | TASK [Install ansible into virtualenv]
2025-10-12 00:19:58.427262 | controller | Processing ./src/github.com/ansible/ansible
2025-10-12 00:19:58.433660 | controller |   Installing build dependencies: started
2025-10-12 00:20:00.740909 | controller |   Installing build dependencies: finished with status 'done'
2025-10-12 00:20:00.744267 | controller |   Getting requirements to build wheel: started
2025-10-12 00:20:02.645692 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-12 00:20:03.683139 | controller |   Preparing metadata (pyproject.toml): started
2025-10-12 00:20:03.683202 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-12 00:20:03.690301 | 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-12 00:20:03.698061 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-12 00:20:04.404231 | controller | ERROR
2025-10-12 00:20:04.404636 | controller | {
2025-10-12 00:20:04.404725 | controller |   "delta": "0:00:06.247418",
2025-10-12 00:20:04.404791 | controller |   "end": "2025-10-12 00:20:03.934127",
2025-10-12 00:20:04.404853 | controller |   "msg": "non-zero return code",
2025-10-12 00:20:04.404945 | controller |   "rc": 1,
2025-10-12 00:20:04.405001 | controller |   "start": "2025-10-12 00:19:57.686709"
2025-10-12 00:20:04.405129 | controller | }
failure
2025-10-12 00:20:04.408329 | 
2025-10-12 00:20:04.408433 | PLAY RECAP
2025-10-12 00:20:04.408520 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-12 00:20:04.408564 | 
2025-10-12 00:20:04.580454 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-12 00:20:04.581571 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-12 00:20:05.284286 | 
2025-10-12 00:20:05.284452 | PLAY [all]
2025-10-12 00:20:05.308612 | 
2025-10-12 00:20:05.308793 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-12 00:20:07.289437 | controller | changed: non-zero return code
2025-10-12 00:20:07.298358 | 
2025-10-12 00:20:07.298533 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-12 00:20:07.324263 | controller | skipping: Conditional result was False
2025-10-12 00:20:07.333469 | 
2025-10-12 00:20:07.333628 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-12 00:20:07.373475 | 
2025-10-12 00:20:07.373717 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-12 00:20:07.410493 | 
2025-10-12 00:20:07.410918 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-12 00:20:07.436963 | controller | skipping: Conditional result was False
2025-10-12 00:20:07.447483 | 
2025-10-12 00:20:07.447639 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-12 00:20:07.480974 | 
2025-10-12 00:20:07.481215 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-12 00:20:07.506847 | controller | skipping: Conditional result was False
2025-10-12 00:20:07.514454 | 
2025-10-12 00:20:07.514585 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-12 00:20:07.540161 | controller | skipping: Conditional result was False
2025-10-12 00:20:07.550842 | 
2025-10-12 00:20:07.551122 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-12 00:20:07.579162 | controller | skipping: Conditional result was False
2025-10-12 00:20:07.612656 | 
2025-10-12 00:20:07.613245 | PLAY RECAP
2025-10-12 00:20:07.613342 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-12 00:20:07.613391 | 
2025-10-12 00:20:07.809149 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-12 00:20:07.810353 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-12 00:20:08.595134 | 
2025-10-12 00:20:08.595409 | PLAY [all:!appliance*]
2025-10-12 00:20:08.622505 | 
2025-10-12 00:20:08.622704 | TASK [unregister the node]
2025-10-12 00:20:08.985549 | controller | skipping: Conditional result was False
2025-10-12 00:20:08.994812 | 
2025-10-12 00:20:08.994928 | TASK [include_role : fetch-output]
2025-10-12 00:20:09.032820 | controller | ok
2025-10-12 00:20:09.062920 | 
2025-10-12 00:20:09.063137 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-12 00:20:09.111380 | controller | skipping: Conditional result was False
2025-10-12 00:20:09.118799 | 
2025-10-12 00:20:09.118938 | TASK [fetch-output : Set log path for single node]
2025-10-12 00:20:09.163530 | controller | ok
2025-10-12 00:20:09.169350 | 
2025-10-12 00:20:09.169507 | LOOP [fetch-output : Ensure local output dirs]
2025-10-12 00:20:09.693488 | controller -> localhost | ok: "/var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/work/logs"
2025-10-12 00:20:09.954872 | controller -> localhost | changed: "/var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/work/artifacts"
2025-10-12 00:20:10.232905 | controller -> localhost | changed: "/var/lib/zuul/builds/bd0f8ee55a6c4d42856ccff68e99b536/work/docs"
2025-10-12 00:20:10.253961 | 
2025-10-12 00:20:10.254167 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-12 00:20:12.635990 | controller | changed:
2025-10-12 00:20:12.636323 | controller | .d..t...... ./
2025-10-12 00:20:12.636362 | controller | cd+++++++++ controller/
2025-10-12 00:20:12.636406 | controller | changed: All items complete
2025-10-12 00:20:12.636434 | 
2025-10-12 00:20:14.747456 | controller | changed: .d..t...... ./
2025-10-12 00:20:16.820829 | controller | changed: .d..t...... ./
2025-10-12 00:20:16.837329 | 
2025-10-12 00:20:16.837482 | TASK [include_role : fetch-output-openshift]
2025-10-12 00:20:16.852212 | controller | skipping: Conditional result was False
2025-10-12 00:20:16.860934 | 
2025-10-12 00:20:16.861101 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-12 00:20:16.887681 | controller | skipping: Conditional result was False
2025-10-12 00:20:16.897741 | controller | skipping: Conditional result was False
2025-10-12 00:20:16.932938 | 
2025-10-12 00:20:16.933110 | PLAY [localhost]
2025-10-12 00:20:16.946987 | 
2025-10-12 00:20:16.947167 | TASK [Run Zuul manifest role]
2025-10-12 00:20:16.967094 | localhost | ok
2025-10-12 00:20:16.981230 | 
2025-10-12 00:20:16.981393 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-12 00:20:17.411775 | localhost | changed
2025-10-12 00:20:17.417040 | 
2025-10-12 00:20:17.417141 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-12 00:20:17.448203 | localhost | ok
2025-10-12 00:20:17.458772 | 
2025-10-12 00:20:17.458918 | TASK [Set zuul-log-path fact]
2025-10-12 00:20:17.523416 | localhost | ok
2025-10-12 00:20:17.539265 | 
2025-10-12 00:20:17.539455 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-12 00:20:17.570544 | localhost | ok
2025-10-12 00:20:17.579723 | 
2025-10-12 00:20:17.579880 | LOOP [Run upload-logs-swift role]
2025-10-12 00:20:17.641221 | localhost | Output suppressed because no_log was given
2025-10-12 00:20:17.679257 | 
2025-10-12 00:20:17.679447 | TASK [Set zuul-log-path fact]
2025-10-12 00:20:17.716337 | localhost | skipping: Conditional result was False
2025-10-12 00:20:17.725175 | 
2025-10-12 00:20:17.725356 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-12 00:20:18.186983 | localhost -> localhost | ok: Runtime: 0:00:00.008565
2025-10-12 00:20:18.197970 | 
2025-10-12 00:20:18.198194 | TASK [upload-logs-swift : Upload logs to swift]