2025-10-23 00:06:32.930045 | Job console starting...
2025-10-23 00:06:32.941058 | Updating repositories
2025-10-23 00:06:33.112420 | Preparing job workspace
2025-10-23 00:06:38.714612 | Running Ansible setup...
2025-10-23 00:06:45.168533 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-23 00:06:45.798711 | 
2025-10-23 00:06:45.798849 | PLAY [localhost]
2025-10-23 00:06:45.808406 | 
2025-10-23 00:06:45.808542 | TASK [Gathering Facts]
2025-10-23 00:06:46.834512 | localhost | ok
2025-10-23 00:06:46.850426 | 
2025-10-23 00:06:46.850562 | TASK [Setup log path fact]
2025-10-23 00:06:46.871323 | localhost | ok
2025-10-23 00:06:46.889957 | 
2025-10-23 00:06:46.890114 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-23 00:06:46.920820 | localhost | ok
2025-10-23 00:06:46.932695 | 
2025-10-23 00:06:46.932823 | TASK [emit-job-header : Print job information]
2025-10-23 00:06:46.972413 | # Job Information
2025-10-23 00:06:46.972563 | Ansible Version: 2.15.12
2025-10-23 00:06:46.972595 | Job: ansible-test-sanity-docker-devel
2025-10-23 00:06:46.972617 | Pipeline: periodic
2025-10-23 00:06:46.972636 | Executor: ze01.softwarefactory-project.io
2025-10-23 00:06:46.972654 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-23 00:06:46.972675 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/5c7/ansible/5c7243053328456ea177307d59042940/
2025-10-23 00:06:46.972695 | Event ID: 0b277d6fb2034b3eb017dadc7a95f30f
2025-10-23 00:06:46.977061 | 
2025-10-23 00:06:46.977168 | LOOP [emit-job-header : Print node information]
2025-10-23 00:06:47.090695 | localhost | ok:
2025-10-23 00:06:47.090956 | localhost | # Node Information
2025-10-23 00:06:47.090986 | localhost | Inventory Hostname: controller
2025-10-23 00:06:47.091007 | localhost | Hostname: ip-172-16-182-208
2025-10-23 00:06:47.091044 | localhost | Username: zuul-worker
2025-10-23 00:06:47.091066 | localhost | Distro: Fedora 37
2025-10-23 00:06:47.091086 | localhost | Provider: ansible-us-east-2
2025-10-23 00:06:47.091104 | localhost | Region: us-east-2
2025-10-23 00:06:47.091121 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-23 00:06:47.091139 | localhost | Product Name: t3.small
2025-10-23 00:06:47.091156 | localhost | Interface IP: 18.188.141.170
2025-10-23 00:06:47.106072 | 
2025-10-23 00:06:47.106271 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-23 00:06:47.520393 | localhost -> localhost | changed
2025-10-23 00:06:47.528907 | 
2025-10-23 00:06:47.529071 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-23 00:06:48.446228 | localhost -> localhost | changed
2025-10-23 00:06:48.466006 | 
2025-10-23 00:06:48.466096 | PLAY [all:!appliance*]
2025-10-23 00:06:48.481684 | 
2025-10-23 00:06:48.481759 | TASK [include_role : start-zuul-console]
2025-10-23 00:06:48.500934 | controller | ok
2025-10-23 00:06:48.515438 | 
2025-10-23 00:06:48.515534 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-23 00:06:49.171720 | controller | ok
2025-10-23 00:06:49.195188 | 
2025-10-23 00:06:49.195334 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-23 00:06:50.610229 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-23 00:06:50.620733 | 
2025-10-23 00:06:50.620895 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-23 00:06:50.773301 | controller | skipping: Conditional result was False
2025-10-23 00:06:50.782430 | 
2025-10-23 00:06:50.782548 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-23 00:06:50.807557 | controller | skipping: Conditional result was False
2025-10-23 00:06:50.816950 | 
2025-10-23 00:06:50.817093 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-23 00:06:50.860865 | controller | skipping: Conditional result was False
2025-10-23 00:06:50.874955 | 
2025-10-23 00:06:50.875214 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-23 00:06:50.892638 | controller | skipping: Conditional result was False
2025-10-23 00:06:50.908273 | 
2025-10-23 00:06:50.908439 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-23 00:06:50.935650 | controller | skipping: Conditional result was False
2025-10-23 00:06:50.943779 | 
2025-10-23 00:06:50.943892 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-23 00:06:50.968937 | controller | skipping: Conditional result was False
2025-10-23 00:06:50.984775 | 
2025-10-23 00:06:50.984895 | TASK [Disable Fedora Modular]
2025-10-23 00:06:51.770539 | controller | changed
2025-10-23 00:06:51.783522 | 
2025-10-23 00:06:51.783676 | TASK [Enable EPEL]
2025-10-23 00:06:51.811331 | controller | skipping: Conditional result was False
2025-10-23 00:06:51.824628 | 
2025-10-23 00:06:51.824788 | TASK [Register the RHEL node]
2025-10-23 00:06:51.992604 | 
2025-10-23 00:06:51.992827 | TASK [Show the subscription-manager status]
2025-10-23 00:06:52.144438 | controller | skipping: Conditional result was False
2025-10-23 00:06:52.199315 | 
2025-10-23 00:06:52.199480 | TASK [Enable EPEL on RHEL]
2025-10-23 00:06:52.342934 | controller | skipping: Conditional result was False
2025-10-23 00:06:52.350486 | 
2025-10-23 00:06:52.350601 | TASK [Install git and tox]
2025-10-23 00:08:21.702745 | controller | changed
2025-10-23 00:08:21.712792 | 
2025-10-23 00:08:21.712982 | TASK [include_role : prepare-workspace]
2025-10-23 00:08:21.750695 | controller | ok
2025-10-23 00:08:21.782455 | 
2025-10-23 00:08:21.782598 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-23 00:08:22.279660 | controller | ok
2025-10-23 00:08:22.292944 | 
2025-10-23 00:08:22.293094 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-23 00:08:46.019183 | controller | Output suppressed because no_log was given
2025-10-23 00:08:46.034653 | 
2025-10-23 00:08:46.034765 | TASK [include_role : prepare-workspace-openshift]
2025-10-23 00:08:46.060217 | controller | skipping: Conditional result was False
2025-10-23 00:08:46.093615 | 
2025-10-23 00:08:46.093703 | PLAY [all:!appliance]
2025-10-23 00:08:46.112273 | 
2025-10-23 00:08:46.112381 | TASK [Run add-build-sshkey role (RSA)]
2025-10-23 00:08:46.166909 | controller | ok
2025-10-23 00:08:46.186953 | 
2025-10-23 00:08:46.187074 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-23 00:08:46.475949 | controller -> localhost | ok
2025-10-23 00:08:46.484328 | 
2025-10-23 00:08:46.484473 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-23 00:08:46.521746 | controller | ok
2025-10-23 00:08:46.568992 | controller | included: /var/lib/zuul/builds/5c7243053328456ea177307d59042940/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-23 00:08:46.583912 | 
2025-10-23 00:08:46.584101 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-23 00:08:47.284629 | controller -> localhost | Generating public/private rsa key pair.
2025-10-23 00:08:47.284893 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5c7243053328456ea177307d59042940/work/5c7243053328456ea177307d59042940_id_rsa.
2025-10-23 00:08:47.284963 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5c7243053328456ea177307d59042940/work/5c7243053328456ea177307d59042940_id_rsa.pub.
2025-10-23 00:08:47.285000 | controller -> localhost | The key fingerprint is:
2025-10-23 00:08:47.285067 | controller -> localhost | SHA256:auN9kn8PtD9eENk9vdbMWOeNqztSVYoIIvj6Y2OZrYk zuul-build-sshkey
2025-10-23 00:08:47.285099 | controller -> localhost | The key's randomart image is:
2025-10-23 00:08:47.285126 | controller -> localhost | +---[RSA 2048]----+
2025-10-23 00:08:47.285150 | controller -> localhost | |   .             |
2025-10-23 00:08:47.285176 | controller -> localhost | |  . . . .      o+|
2025-10-23 00:08:47.285200 | controller -> localhost | |   . . . . . .o+*|
2025-10-23 00:08:47.285224 | controller -> localhost | |    .     . . oO*|
2025-10-23 00:08:47.285247 | controller -> localhost | |   .    S   ..+o*|
2025-10-23 00:08:47.285285 | controller -> localhost | |  .    .   ....o |
2025-10-23 00:08:47.285316 | controller -> localhost | |   . ++  . .o . .|
2025-10-23 00:08:47.285341 | controller -> localhost | |   .O+.oo o o+.. |
2025-10-23 00:08:47.285366 | controller -> localhost | |  Eoo+. .+.oo=+. |
2025-10-23 00:08:47.285395 | controller -> localhost | +----[SHA256]-----+
2025-10-23 00:08:47.285454 | controller -> localhost | ok: Runtime: 0:00:00.216728
2025-10-23 00:08:47.297259 | 
2025-10-23 00:08:47.297408 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-23 00:08:47.336815 | controller | ok
2025-10-23 00:08:47.406856 | controller | included: /var/lib/zuul/builds/5c7243053328456ea177307d59042940/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-23 00:08:47.420075 | 
2025-10-23 00:08:47.420182 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-23 00:08:47.449006 | controller | skipping: Conditional result was False
2025-10-23 00:08:47.460933 | 
2025-10-23 00:08:47.461055 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-23 00:08:48.097583 | controller | changed
2025-10-23 00:08:48.105078 | 
2025-10-23 00:08:48.105172 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-23 00:08:48.453263 | controller | ok
2025-10-23 00:08:48.464881 | 
2025-10-23 00:08:48.465077 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-23 00:08:49.807620 | controller | changed
2025-10-23 00:08:49.815078 | 
2025-10-23 00:08:49.815167 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-23 00:08:51.152991 | controller | changed
2025-10-23 00:08:51.168910 | 
2025-10-23 00:08:51.169152 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-23 00:08:51.205979 | controller | skipping: Conditional result was False
2025-10-23 00:08:51.212658 | 
2025-10-23 00:08:51.212736 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-23 00:08:51.575084 | controller -> localhost | changed
2025-10-23 00:08:51.589997 | 
2025-10-23 00:08:51.590259 | TASK [add-build-sshkey : Add back temp key]
2025-10-23 00:08:51.923654 | controller -> localhost | Identity added: /var/lib/zuul/builds/5c7243053328456ea177307d59042940/work/5c7243053328456ea177307d59042940_id_rsa (zuul-build-sshkey)
2025-10-23 00:08:51.923926 | controller -> localhost | ok: Runtime: 0:00:00.008528
2025-10-23 00:08:51.931090 | 
2025-10-23 00:08:51.931186 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-23 00:08:52.478872 | controller | ok
2025-10-23 00:08:52.488687 | 
2025-10-23 00:08:52.488834 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-23 00:08:52.536187 | controller | skipping: Conditional result was False
2025-10-23 00:08:52.556533 | 
2025-10-23 00:08:52.556680 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-23 00:08:52.588093 | controller | ok
2025-10-23 00:08:52.607112 | 
2025-10-23 00:08:52.607232 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-23 00:08:52.835557 | controller -> localhost | ok
2025-10-23 00:08:52.843596 | 
2025-10-23 00:08:52.843729 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-23 00:08:52.874536 | controller | ok
2025-10-23 00:08:52.887903 | controller | included: /var/lib/zuul/builds/5c7243053328456ea177307d59042940/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-23 00:08:52.897153 | 
2025-10-23 00:08:52.897307 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-23 00:08:53.198517 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-23 00:08:53.198745 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5c7243053328456ea177307d59042940/work/5c7243053328456ea177307d59042940_id_ecdsa.
2025-10-23 00:08:53.198786 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5c7243053328456ea177307d59042940/work/5c7243053328456ea177307d59042940_id_ecdsa.pub.
2025-10-23 00:08:53.198864 | controller -> localhost | The key fingerprint is:
2025-10-23 00:08:53.198894 | controller -> localhost | SHA256:tQUQqSI0GMN8QVfiiBtjwxMrPy6E0zc9vmcm9nwN+cI zuul-build-sshkey
2025-10-23 00:08:53.198921 | controller -> localhost | The key's randomart image is:
2025-10-23 00:08:53.198948 | controller -> localhost | +---[ECDSA 521]---+
2025-10-23 00:08:53.198973 | controller -> localhost | |=+.o.o..o+.      |
2025-10-23 00:08:53.199000 | controller -> localhost | |o+*.+ . .  .     |
2025-10-23 00:08:53.199052 | controller -> localhost | |.@.o . .  . .    |
2025-10-23 00:08:53.199078 | controller -> localhost | |+oB ...  . o     |
2025-10-23 00:08:53.199097 | controller -> localhost | |oo+.o.o S ..     |
2025-10-23 00:08:53.199116 | controller -> localhost | |.o o o .  o      |
2025-10-23 00:08:53.199141 | controller -> localhost | |. .   .  . +     |
2025-10-23 00:08:53.199169 | controller -> localhost | | .    oo+ E o    |
2025-10-23 00:08:53.199195 | controller -> localhost | |     ..*o. .     |
2025-10-23 00:08:53.199223 | controller -> localhost | +----[SHA256]-----+
2025-10-23 00:08:53.199287 | controller -> localhost | ok: Runtime: 0:00:00.009001
2025-10-23 00:08:53.207886 | 
2025-10-23 00:08:53.208172 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-23 00:08:53.241835 | controller | ok
2025-10-23 00:08:53.249405 | controller | included: /var/lib/zuul/builds/5c7243053328456ea177307d59042940/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-23 00:08:53.258891 | 
2025-10-23 00:08:53.258982 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-23 00:08:53.284025 | controller | skipping: Conditional result was False
2025-10-23 00:08:53.290398 | 
2025-10-23 00:08:53.290467 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-23 00:08:53.751770 | controller | changed
2025-10-23 00:08:53.760460 | 
2025-10-23 00:08:53.760607 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-23 00:08:54.104735 | controller | ok
2025-10-23 00:08:54.124798 | 
2025-10-23 00:08:54.124914 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-23 00:08:55.479193 | controller | changed
2025-10-23 00:08:55.487994 | 
2025-10-23 00:08:55.488136 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-23 00:08:57.275432 | controller | changed
2025-10-23 00:08:57.281791 | 
2025-10-23 00:08:57.281913 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-23 00:08:57.307485 | controller | skipping: Conditional result was False
2025-10-23 00:08:57.314577 | 
2025-10-23 00:08:57.314672 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-23 00:08:57.604453 | controller -> localhost | changed
2025-10-23 00:08:57.624744 | 
2025-10-23 00:08:57.624879 | TASK [add-build-sshkey : Add back temp key]
2025-10-23 00:08:57.896416 | controller -> localhost | Identity added: /var/lib/zuul/builds/5c7243053328456ea177307d59042940/work/5c7243053328456ea177307d59042940_id_ecdsa (zuul-build-sshkey)
2025-10-23 00:08:57.896735 | controller -> localhost | ok: Runtime: 0:00:00.012628
2025-10-23 00:08:57.905743 | 
2025-10-23 00:08:57.905856 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-23 00:08:58.242308 | controller | ok
2025-10-23 00:08:58.255783 | 
2025-10-23 00:08:58.255956 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-23 00:08:58.284886 | controller | skipping: Conditional result was False
2025-10-23 00:08:58.318865 | 
2025-10-23 00:08:58.319067 | TASK [include_role : remove-zuul-sshkey]
2025-10-23 00:08:58.346176 | controller | skipping: Conditional result was False
2025-10-23 00:08:58.392888 | 
2025-10-23 00:08:58.393050 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-23 00:08:58.740606 | controller | ok: "logs"
2025-10-23 00:08:58.741262 | controller | ok: All items complete
2025-10-23 00:08:58.741356 | 
2025-10-23 00:08:59.041753 | controller | ok: "artifacts"
2025-10-23 00:08:59.366341 | controller | ok: "docs"
2025-10-23 00:08:59.389925 | 
2025-10-23 00:08:59.390380 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-23 00:08:59.765205 | controller | changed: "logs"
2025-10-23 00:09:00.194788 | controller | changed: "artifacts"
2025-10-23 00:09:00.669860 | controller | changed: "docs"
2025-10-23 00:09:00.715769 | 
2025-10-23 00:09:00.715912 | PLAY RECAP
2025-10-23 00:09:00.716102 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-23 00:09:00.716179 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-23 00:09:00.716223 | 
2025-10-23 00:09:00.842541 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-23 00:09:00.843435 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-23 00:09:01.458883 | 
2025-10-23 00:09:01.459036 | PLAY [all]
2025-10-23 00:09:01.483748 | 
2025-10-23 00:09:01.483907 | TASK [Install binary dependencies]
2025-10-23 00:09:01.533654 | controller | ok
2025-10-23 00:09:01.561732 | 
2025-10-23 00:09:01.561921 | TASK [bindep : Include find tasks]
2025-10-23 00:09:01.592668 | controller | ok
2025-10-23 00:09:01.601068 | controller | included: /var/lib/zuul/builds/5c7243053328456ea177307d59042940/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-23 00:09:01.607563 | 
2025-10-23 00:09:01.607646 | TASK [bindep : Look for bindep.txt]
2025-10-23 00:09:02.647987 | controller | ok
2025-10-23 00:09:02.662371 | 
2025-10-23 00:09:02.662580 | TASK [bindep : Define bindep_file fact]
2025-10-23 00:09:02.678294 | controller | skipping: Conditional result was False
2025-10-23 00:09:02.688101 | 
2025-10-23 00:09:02.688239 | TASK [bindep : Look for other-requirements.txt]
2025-10-23 00:09:03.313212 | controller | ok
2025-10-23 00:09:03.319612 | 
2025-10-23 00:09:03.319699 | TASK [bindep : Define bindep_file fact]
2025-10-23 00:09:03.343999 | controller | skipping: Conditional result was False
2025-10-23 00:09:03.350582 | 
2025-10-23 00:09:03.350680 | TASK [bindep : Look for bindep fallback file]
2025-10-23 00:09:03.384904 | controller | skipping: Conditional result was False
2025-10-23 00:09:03.394222 | 
2025-10-23 00:09:03.394363 | TASK [bindep : Define bindep_file fact]
2025-10-23 00:09:03.420052 | controller | skipping: Conditional result was False
2025-10-23 00:09:03.429696 | 
2025-10-23 00:09:03.429828 | TASK [bindep : Include bindep tasks]
2025-10-23 00:09:03.455178 | controller | skipping: Conditional result was False
2025-10-23 00:09:03.465331 | 
2025-10-23 00:09:03.465474 | TASK [bindep : Include install tasks]
2025-10-23 00:09:03.491157 | controller | skipping: Conditional result was False
2025-10-23 00:09:03.501976 | 
2025-10-23 00:09:03.502198 | LOOP [bindep : Include package tasks]
2025-10-23 00:09:03.574648 | 
2025-10-23 00:09:03.574842 | TASK [Run test-setup role]
2025-10-23 00:09:03.597704 | controller | ok
2025-10-23 00:09:03.627930 | 
2025-10-23 00:09:03.628056 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-23 00:09:03.998784 | controller | ok
2025-10-23 00:09:04.016128 | 
2025-10-23 00:09:04.016302 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-23 00:09:04.169175 | controller | skipping: Conditional result was False
2025-10-23 00:09:04.224928 | 
2025-10-23 00:09:04.225077 | PLAY RECAP
2025-10-23 00:09:04.225135 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-23 00:09:04.225162 | 
2025-10-23 00:09:04.335546 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-23 00:09:04.336414 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-23 00:09:04.960247 | 
2025-10-23 00:09:04.960386 | PLAY [controller]
2025-10-23 00:09:04.981203 | 
2025-10-23 00:09:04.981359 | TASK [Create the /root directory]
2025-10-23 00:09:05.718942 | controller | ok
2025-10-23 00:09:05.734374 | 
2025-10-23 00:09:05.734566 | TASK [Install glibc-langpack-en]
2025-10-23 00:09:13.816610 | controller | ok: Nothing to do
2025-10-23 00:09:13.827097 | 
2025-10-23 00:09:13.827302 | TASK [Ensure controller directory exists]
2025-10-23 00:09:14.298404 | controller | changed
2025-10-23 00:09:14.303924 | 
2025-10-23 00:09:14.303994 | TASK [Install container runtime]
2025-10-23 00:09:14.354438 | controller | ok
2025-10-23 00:09:14.392862 | 
2025-10-23 00:09:14.392982 | LOOP [ensure-podman : Find distribution installation]
2025-10-23 00:09:14.418379 | controller | ok: "/var/lib/zuul/builds/5c7243053328456ea177307d59042940/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-23 00:09:14.425435 | controller | included: /var/lib/zuul/builds/5c7243053328456ea177307d59042940/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-23 00:09:14.431885 | 
2025-10-23 00:09:14.431951 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-23 00:10:31.123808 | controller | changed
2025-10-23 00:10:31.130225 | 
2025-10-23 00:10:31.130294 | TASK [ensure-podman : Fetch podman version]
2025-10-23 00:10:31.868820 | controller | Client:       Podman Engine
2025-10-23 00:10:31.868900 | controller | Version:      4.6.2
2025-10-23 00:10:31.868930 | controller | API Version:  4.6.2
2025-10-23 00:10:31.868956 | controller | Go Version:   go1.19.12
2025-10-23 00:10:31.868993 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-23 00:10:31.869037 | controller | OS/Arch:      linux/amd64
2025-10-23 00:10:32.260240 | controller | ok: Runtime: 0:00:00.223413
2025-10-23 00:10:32.266722 | 
2025-10-23 00:10:32.266817 | TASK [ensure-podman : Print podman version installed]
2025-10-23 00:10:32.297269 | Podman version: Client:       Podman Engine
2025-10-23 00:10:32.297431 | Version:      4.6.2
2025-10-23 00:10:32.297462 | API Version:  4.6.2
2025-10-23 00:10:32.297490 | Go Version:   go1.19.12
2025-10-23 00:10:32.297510 | Built:        Mon Aug 28 19:38:31 2023
2025-10-23 00:10:32.297529 | OS/Arch:      linux/amd64
2025-10-23 00:10:32.303491 | 
2025-10-23 00:10:32.303577 | TASK [ensure-podman : Validate podman engine]
2025-10-23 00:10:32.440675 | controller | skipping: Conditional result was False
2025-10-23 00:10:32.447666 | 
2025-10-23 00:10:32.447789 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-23 00:10:32.473638 | controller | skipping: Conditional result was False
2025-10-23 00:10:32.486659 | 
2025-10-23 00:10:32.486805 | TASK [Ensure python3.8 is present]
2025-10-23 00:10:32.511755 | controller | skipping: Conditional result was False
2025-10-23 00:10:32.521454 | 
2025-10-23 00:10:32.521587 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-23 00:10:32.545249 | controller | ok
2025-10-23 00:10:32.576151 | 
2025-10-23 00:10:32.576287 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-23 00:10:36.188852 | controller | ok: Nothing to do
2025-10-23 00:10:36.204586 | 
2025-10-23 00:10:36.204814 | TASK [our-ensure-python : Also install python3-devel]
2025-10-23 00:10:49.430868 | controller | changed
2025-10-23 00:10:49.449094 | 
2025-10-23 00:10:49.449234 | TASK [Run ensure-virtualenv role]
2025-10-23 00:10:49.470680 | controller | ok
2025-10-23 00:10:49.494598 | 
2025-10-23 00:10:49.494724 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-23 00:10:49.871588 | controller | /usr/bin/virtualenv
2025-10-23 00:10:50.126738 | controller | ok: Runtime: 0:00:00.004361
2025-10-23 00:10:50.136726 | 
2025-10-23 00:10:50.136889 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-23 00:10:50.174739 | controller | skipping: Conditional result was False
2025-10-23 00:10:50.175503 | controller | ok: All items complete
2025-10-23 00:10:50.175583 | 
2025-10-23 00:10:50.202100 | 
2025-10-23 00:10:50.202272 | TASK [Find the full path of the Python interpreter]
2025-10-23 00:10:50.688093 | controller | /usr/bin/python3
2025-10-23 00:10:50.891057 | controller | ok
2025-10-23 00:10:50.904856 | 
2025-10-23 00:10:50.905108 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-23 00:10:52.414644 | controller | created virtual environment CPython3.11.0.final.0-64 in 756ms
2025-10-23 00:10:52.463884 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-23 00:10:52.464186 | 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-23 00:10:52.464208 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-23 00:10:52.464232 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-23 00:10:52.578487 | controller | changed
2025-10-23 00:10:52.592713 | 
2025-10-23 00:10:52.592893 | TASK [Set selinux package]
2025-10-23 00:10:52.626060 | controller | ok
2025-10-23 00:10:52.638354 | 
2025-10-23 00:10:52.638655 | TASK [Set selinux package (Fedora)]
2025-10-23 00:10:52.692537 | controller | ok
2025-10-23 00:10:52.700160 | 
2025-10-23 00:10:52.700304 | TASK [Install selinux into virtualenv]
2025-10-23 00:10:55.283949 | controller | Collecting selinux-please-lie-to-me
2025-10-23 00:10:55.374192 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-23 00:10:55.899828 | controller | Collecting setuptools<50.0.0
2025-10-23 00:10:55.914727 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-23 00:10:55.992143 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 11.2 MB/s eta 0:00:00
2025-10-23 00:10:56.146454 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-23 00:10:56.146760 | controller |   Attempting uninstall: setuptools
2025-10-23 00:10:56.151691 | controller |     Found existing installation: setuptools 62.6.0
2025-10-23 00:10:56.262164 | controller |     Uninstalling setuptools-62.6.0:
2025-10-23 00:10:56.277213 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-23 00:10:57.012477 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-23 00:10:57.216733 | controller |
2025-10-23 00:10:57.424261 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-23 00:10:57.424305 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-23 00:10:57.890594 | controller | ok: Runtime: 0:00:04.254208
2025-10-23 00:10:57.904684 | 
2025-10-23 00:10:57.904925 | TASK [Install pytest-forked into virtualenv]
2025-10-23 00:10:59.126423 | controller | Collecting pytest-forked
2025-10-23 00:10:59.216128 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-23 00:10:59.274504 | controller | Collecting py
2025-10-23 00:10:59.290103 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-23 00:10:59.329756 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.7 MB/s eta 0:00:00
2025-10-23 00:10:59.505993 | controller | Collecting pytest>=3.10
2025-10-23 00:10:59.517930 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-23 00:10:59.580609 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.1 MB/s eta 0:00:00
2025-10-23 00:10:59.639554 | controller | Collecting iniconfig>=1
2025-10-23 00:10:59.651766 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-23 00:10:59.719088 | controller | Collecting packaging>=20
2025-10-23 00:10:59.731205 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-23 00:10:59.745917 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.2 MB/s eta 0:00:00
2025-10-23 00:10:59.793225 | controller | Collecting pluggy<2,>=1.5
2025-10-23 00:10:59.805720 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-23 00:10:59.880169 | controller | Collecting pygments>=2.7.2
2025-10-23 00:10:59.892284 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-23 00:11:00.012718 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.4 MB/s eta 0:00:00
2025-10-23 00:11:00.146923 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-23 00:11:02.402274 | controller | Successfully installed iniconfig-2.3.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-23 00:11:02.418693 | controller |
2025-10-23 00:11:02.613814 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-23 00:11:02.613867 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-23 00:11:03.134608 | controller | ok: Runtime: 0:00:04.210663
2025-10-23 00:11:03.141405 | 
2025-10-23 00:11:03.141479 | TASK [Update pip]
2025-10-23 00:11:04.334979 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-23 00:11:04.625064 | controller | Collecting pip
2025-10-23 00:11:04.726563 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-23 00:11:04.892486 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.8 MB/s eta 0:00:00
2025-10-23 00:11:05.019221 | controller | Installing collected packages: pip
2025-10-23 00:11:05.019672 | controller |   Attempting uninstall: pip
2025-10-23 00:11:05.024321 | controller |     Found existing installation: pip 22.2.2
2025-10-23 00:11:05.286131 | controller |     Uninstalling pip-22.2.2:
2025-10-23 00:11:05.316058 | controller |       Successfully uninstalled pip-22.2.2
2025-10-23 00:11:07.137002 | controller | Successfully installed pip-25.2
2025-10-23 00:11:07.838943 | controller | ok: Runtime: 0:00:03.642073
2025-10-23 00:11:07.851979 | 
2025-10-23 00:11:07.852159 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-23 00:11:08.425469 | controller | changed
2025-10-23 00:11:08.439822 | 
2025-10-23 00:11:08.439983 | TASK [Install ansible into virtualenv]
2025-10-23 00:11:09.566717 | controller | Processing ./src/github.com/ansible/ansible
2025-10-23 00:11:09.574765 | controller |   Installing build dependencies: started
2025-10-23 00:11:11.594285 | controller |   Installing build dependencies: finished with status 'done'
2025-10-23 00:11:13.102886 | controller |   Getting requirements to build wheel: started
2025-10-23 00:11:13.102953 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-23 00:11:14.051073 | controller |   Preparing metadata (pyproject.toml): started
2025-10-23 00:11:14.051129 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-23 00:11:14.055068 | 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-23 00:11:14.055120 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-23 00:11:14.608303 | controller | ERROR
2025-10-23 00:11:14.608596 | controller | {
2025-10-23 00:11:14.608679 | controller |   "delta": "0:00:05.253626",
2025-10-23 00:11:14.608727 | controller |   "end": "2025-10-23 00:11:14.200417",
2025-10-23 00:11:14.608765 | controller |   "msg": "non-zero return code",
2025-10-23 00:11:14.608815 | controller |   "rc": 1,
2025-10-23 00:11:14.608853 | controller |   "start": "2025-10-23 00:11:08.946791"
2025-10-23 00:11:14.608901 | controller | }
failure
2025-10-23 00:11:14.611938 | 
2025-10-23 00:11:14.612093 | PLAY RECAP
2025-10-23 00:11:14.612191 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-23 00:11:14.612334 | 
2025-10-23 00:11:14.753709 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-23 00:11:14.754700 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-23 00:11:15.428724 | 
2025-10-23 00:11:15.428839 | PLAY [all]
2025-10-23 00:11:15.450231 | 
2025-10-23 00:11:15.450329 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-23 00:11:16.263440 | controller | changed: non-zero return code
2025-10-23 00:11:16.271628 | 
2025-10-23 00:11:16.271739 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-23 00:11:16.297065 | controller | skipping: Conditional result was False
2025-10-23 00:11:16.305100 | 
2025-10-23 00:11:16.305204 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-23 00:11:16.338803 | 
2025-10-23 00:11:16.339009 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-23 00:11:16.371694 | 
2025-10-23 00:11:16.371878 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-23 00:11:16.397187 | controller | skipping: Conditional result was False
2025-10-23 00:11:16.403533 | 
2025-10-23 00:11:16.403621 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-23 00:11:16.434952 | 
2025-10-23 00:11:16.435153 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-23 00:11:16.460086 | controller | skipping: Conditional result was False
2025-10-23 00:11:16.468453 | 
2025-10-23 00:11:16.468549 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-23 00:11:16.484326 | controller | skipping: Conditional result was False
2025-10-23 00:11:16.491703 | 
2025-10-23 00:11:16.491787 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-23 00:11:16.516151 | controller | skipping: Conditional result was False
2025-10-23 00:11:16.573711 | 
2025-10-23 00:11:16.573834 | PLAY RECAP
2025-10-23 00:11:16.573890 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-23 00:11:16.573918 | 
2025-10-23 00:11:16.681970 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-23 00:11:16.682810 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-23 00:11:17.325405 | 
2025-10-23 00:11:17.325531 | PLAY [all:!appliance*]
2025-10-23 00:11:17.347315 | 
2025-10-23 00:11:17.347445 | TASK [unregister the node]
2025-10-23 00:11:17.492156 | controller | skipping: Conditional result was False
2025-10-23 00:11:17.500377 | 
2025-10-23 00:11:17.500576 | TASK [include_role : fetch-output]
2025-10-23 00:11:17.549721 | controller | ok
2025-10-23 00:11:17.581959 | 
2025-10-23 00:11:17.582163 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-23 00:11:17.641920 | controller | skipping: Conditional result was False
2025-10-23 00:11:17.647890 | 
2025-10-23 00:11:17.647973 | TASK [fetch-output : Set log path for single node]
2025-10-23 00:11:17.687356 | controller | ok
2025-10-23 00:11:17.693224 | 
2025-10-23 00:11:17.693310 | LOOP [fetch-output : Ensure local output dirs]
2025-10-23 00:11:18.122669 | controller -> localhost | ok: "/var/lib/zuul/builds/5c7243053328456ea177307d59042940/work/logs"
2025-10-23 00:11:18.348993 | controller -> localhost | changed: "/var/lib/zuul/builds/5c7243053328456ea177307d59042940/work/artifacts"
2025-10-23 00:11:18.590764 | controller -> localhost | changed: "/var/lib/zuul/builds/5c7243053328456ea177307d59042940/work/docs"
2025-10-23 00:11:18.605431 | 
2025-10-23 00:11:18.605560 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-23 00:11:19.862944 | controller | changed:
2025-10-23 00:11:19.863318 | controller | .d..t...... ./
2025-10-23 00:11:19.863380 | controller | cd+++++++++ controller/
2025-10-23 00:11:19.863454 | controller | changed: All items complete
2025-10-23 00:11:19.863499 | 
2025-10-23 00:11:20.873890 | controller | changed: .d..t...... ./
2025-10-23 00:11:21.983991 | controller | changed: .d..t...... ./
2025-10-23 00:11:22.012576 | 
2025-10-23 00:11:22.012725 | TASK [include_role : fetch-output-openshift]
2025-10-23 00:11:22.028157 | controller | skipping: Conditional result was False
2025-10-23 00:11:22.038475 | 
2025-10-23 00:11:22.038629 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-23 00:11:22.065837 | controller | skipping: Conditional result was False
2025-10-23 00:11:22.075532 | controller | skipping: Conditional result was False
2025-10-23 00:11:22.132512 | 
2025-10-23 00:11:22.132645 | PLAY [localhost]
2025-10-23 00:11:22.152438 | 
2025-10-23 00:11:22.152839 | TASK [Run Zuul manifest role]
2025-10-23 00:11:22.174294 | localhost | ok
2025-10-23 00:11:22.196936 | 
2025-10-23 00:11:22.197118 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-23 00:11:22.605897 | localhost | changed
2025-10-23 00:11:22.612579 | 
2025-10-23 00:11:22.612680 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-23 00:11:22.656405 | localhost | ok
2025-10-23 00:11:22.670431 | 
2025-10-23 00:11:22.670612 | TASK [Set zuul-log-path fact]
2025-10-23 00:11:22.693383 | localhost | ok
2025-10-23 00:11:22.713969 | 
2025-10-23 00:11:22.714112 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-23 00:11:22.753740 | localhost | ok
2025-10-23 00:11:22.763723 | 
2025-10-23 00:11:22.763808 | LOOP [Run upload-logs-swift role]
2025-10-23 00:11:22.813129 | localhost | Output suppressed because no_log was given
2025-10-23 00:11:22.840795 | 
2025-10-23 00:11:22.840908 | TASK [Set zuul-log-path fact]
2025-10-23 00:11:22.875498 | localhost | skipping: Conditional result was False
2025-10-23 00:11:22.884253 | 
2025-10-23 00:11:22.884387 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-23 00:11:23.319500 | localhost -> localhost | ok: Runtime: 0:00:00.006592
2025-10-23 00:11:23.326048 | 
2025-10-23 00:11:23.326150 | TASK [upload-logs-swift : Upload logs to swift]