2025-09-27 00:06:33.951037 | Job console starting...
2025-09-27 00:06:33.963141 | Updating repositories
2025-09-27 00:06:34.152657 | Preparing job workspace
2025-09-27 00:06:40.785393 | Running Ansible setup...
2025-09-27 00:06:46.826815 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-27 00:06:47.406099 | 
2025-09-27 00:06:47.406216 | PLAY [localhost]
2025-09-27 00:06:47.414510 | 
2025-09-27 00:06:47.414579 | TASK [Gathering Facts]
2025-09-27 00:06:48.440073 | localhost | ok
2025-09-27 00:06:48.468215 | 
2025-09-27 00:06:48.468352 | TASK [Setup log path fact]
2025-09-27 00:06:48.488624 | localhost | ok
2025-09-27 00:06:48.507958 | 
2025-09-27 00:06:48.508081 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-27 00:06:48.538417 | localhost | ok
2025-09-27 00:06:48.549897 | 
2025-09-27 00:06:48.549992 | TASK [emit-job-header : Print job information]
2025-09-27 00:06:48.590299 | # Job Information
2025-09-27 00:06:48.590450 | Ansible Version: 2.15.12
2025-09-27 00:06:48.590497 | Job: ansible-test-sanity-docker-devel
2025-09-27 00:06:48.590529 | Pipeline: periodic
2025-09-27 00:06:48.590556 | Executor: ze04.softwarefactory-project.io
2025-09-27 00:06:48.590584 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-27 00:06:48.590615 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/209/ansible/2092fa999a77420687fe9dd02e148ce8/
2025-09-27 00:06:48.590644 | Event ID: 6059628ede9d40b08c9c7e960ce1822b
2025-09-27 00:06:48.596308 | 
2025-09-27 00:06:48.596403 | LOOP [emit-job-header : Print node information]
2025-09-27 00:06:48.711206 | localhost | ok:
2025-09-27 00:06:48.711462 | localhost | # Node Information
2025-09-27 00:06:48.711498 | localhost | Inventory Hostname: controller
2025-09-27 00:06:48.711521 | localhost | Hostname: ip-172-16-197-76
2025-09-27 00:06:48.711541 | localhost | Username: zuul-worker
2025-09-27 00:06:48.711563 | localhost | Distro: Fedora 37
2025-09-27 00:06:48.711583 | localhost | Provider: ansible-us-east-2
2025-09-27 00:06:48.711602 | localhost | Region: us-east-2
2025-09-27 00:06:48.711619 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-27 00:06:48.711637 | localhost | Product Name: t3.small
2025-09-27 00:06:48.711655 | localhost | Interface IP: 3.150.132.34
2025-09-27 00:06:48.738033 | 
2025-09-27 00:06:48.738222 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-27 00:06:49.149876 | localhost -> localhost | changed
2025-09-27 00:06:49.164546 | 
2025-09-27 00:06:49.164800 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-27 00:06:50.134255 | localhost -> localhost | changed
2025-09-27 00:06:50.156209 | 
2025-09-27 00:06:50.156329 | PLAY [all:!appliance*]
2025-09-27 00:06:50.173996 | 
2025-09-27 00:06:50.174111 | TASK [include_role : start-zuul-console]
2025-09-27 00:06:50.193571 | controller | ok
2025-09-27 00:06:50.207759 | 
2025-09-27 00:06:50.207858 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-27 00:06:50.903234 | controller | ok
2025-09-27 00:06:50.920603 | 
2025-09-27 00:06:50.920801 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-27 00:06:52.541430 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-27 00:06:52.559362 | 
2025-09-27 00:06:52.559560 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-27 00:06:52.716808 | controller | skipping: Conditional result was False
2025-09-27 00:06:52.730928 | 
2025-09-27 00:06:52.731213 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-27 00:06:52.758277 | controller | skipping: Conditional result was False
2025-09-27 00:06:52.772051 | 
2025-09-27 00:06:52.772203 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-27 00:06:52.797454 | controller | skipping: Conditional result was False
2025-09-27 00:06:52.807872 | 
2025-09-27 00:06:52.807965 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-27 00:06:52.833185 | controller | skipping: Conditional result was False
2025-09-27 00:06:52.843153 | 
2025-09-27 00:06:52.843282 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-27 00:06:52.884087 | controller | skipping: Conditional result was False
2025-09-27 00:06:52.898977 | 
2025-09-27 00:06:52.899160 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-27 00:06:52.926188 | controller | skipping: Conditional result was False
2025-09-27 00:06:52.954525 | 
2025-09-27 00:06:52.954730 | TASK [Disable Fedora Modular]
2025-09-27 00:06:53.706933 | controller | changed
2025-09-27 00:06:53.725526 | 
2025-09-27 00:06:53.725723 | TASK [Enable EPEL]
2025-09-27 00:06:53.753075 | controller | skipping: Conditional result was False
2025-09-27 00:06:53.768400 | 
2025-09-27 00:06:53.768551 | TASK [Register the RHEL node]
2025-09-27 00:06:53.926262 | 
2025-09-27 00:06:53.926454 | TASK [Show the subscription-manager status]
2025-09-27 00:06:54.084013 | controller | skipping: Conditional result was False
2025-09-27 00:06:54.126074 | 
2025-09-27 00:06:54.126223 | TASK [Enable EPEL on RHEL]
2025-09-27 00:06:54.266114 | controller | skipping: Conditional result was False
2025-09-27 00:06:54.275133 | 
2025-09-27 00:06:54.275262 | TASK [Install git and tox]
2025-09-27 00:08:20.023371 | controller | changed
2025-09-27 00:08:20.035855 | 
2025-09-27 00:08:20.035981 | TASK [include_role : prepare-workspace]
2025-09-27 00:08:20.061324 | controller | ok
2025-09-27 00:08:20.091993 | 
2025-09-27 00:08:20.092106 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-27 00:08:20.583446 | controller | ok
2025-09-27 00:08:20.593656 | 
2025-09-27 00:08:20.593828 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-27 00:08:43.610468 | controller | Output suppressed because no_log was given
2025-09-27 00:08:43.630123 | 
2025-09-27 00:08:43.630264 | TASK [include_role : prepare-workspace-openshift]
2025-09-27 00:08:43.712627 | controller | skipping: Conditional result was False
2025-09-27 00:08:43.772951 | 
2025-09-27 00:08:43.773030 | PLAY [all:!appliance]
2025-09-27 00:08:43.789950 | 
2025-09-27 00:08:43.790060 | TASK [Run add-build-sshkey role (RSA)]
2025-09-27 00:08:43.811224 | controller | ok
2025-09-27 00:08:43.830703 | 
2025-09-27 00:08:43.830819 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-27 00:08:44.059294 | controller -> localhost | ok
2025-09-27 00:08:44.065335 | 
2025-09-27 00:08:44.065489 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-27 00:08:44.087242 | controller | ok
2025-09-27 00:08:44.105394 | controller | included: /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-27 00:08:44.116028 | 
2025-09-27 00:08:44.116347 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-27 00:08:44.610479 | controller -> localhost | Generating public/private rsa key pair.
2025-09-27 00:08:44.610658 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/work/2092fa999a77420687fe9dd02e148ce8_id_rsa.
2025-09-27 00:08:44.610705 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/work/2092fa999a77420687fe9dd02e148ce8_id_rsa.pub.
2025-09-27 00:08:44.610728 | controller -> localhost | The key fingerprint is:
2025-09-27 00:08:44.610749 | controller -> localhost | SHA256:pEZPVvMUFtKLYik7WPZaCtWyZoId2/Kr112Pl0fKtas zuul-build-sshkey
2025-09-27 00:08:44.610769 | controller -> localhost | The key's randomart image is:
2025-09-27 00:08:44.610788 | controller -> localhost | +---[RSA 2048]----+
2025-09-27 00:08:44.610806 | controller -> localhost | |          +.=o   |
2025-09-27 00:08:44.610827 | controller -> localhost | |         . *.    |
2025-09-27 00:08:44.610846 | controller -> localhost | |      ..+. ...   |
2025-09-27 00:08:44.610864 | controller -> localhost | |    ..**= . .    |
2025-09-27 00:08:44.610882 | controller -> localhost | |   o OoBS.       |
2025-09-27 00:08:44.610908 | controller -> localhost | |  . B.B o   .   o|
2025-09-27 00:08:44.610933 | controller -> localhost | |     B * . . + =.|
2025-09-27 00:08:44.610954 | controller -> localhost | |      = . . . *..|
2025-09-27 00:08:44.610973 | controller -> localhost | |    .o..     E.o.|
2025-09-27 00:08:44.610994 | controller -> localhost | +----[SHA256]-----+
2025-09-27 00:08:44.611039 | controller -> localhost | ok: Runtime: 0:00:00.096803
2025-09-27 00:08:44.617418 | 
2025-09-27 00:08:44.617479 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-27 00:08:44.637315 | controller | ok
2025-09-27 00:08:44.648549 | controller | included: /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-27 00:08:44.658227 | 
2025-09-27 00:08:44.658355 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-27 00:08:44.672791 | controller | skipping: Conditional result was False
2025-09-27 00:08:44.680590 | 
2025-09-27 00:08:44.680669 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-27 00:08:45.340606 | controller | changed
2025-09-27 00:08:45.353805 | 
2025-09-27 00:08:45.353946 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-27 00:08:45.695066 | controller | ok
2025-09-27 00:08:45.705445 | 
2025-09-27 00:08:45.705568 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-27 00:08:47.106452 | controller | changed
2025-09-27 00:08:47.116420 | 
2025-09-27 00:08:47.116609 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-27 00:08:48.357226 | controller | changed
2025-09-27 00:08:48.375560 | 
2025-09-27 00:08:48.375931 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-27 00:08:48.412647 | controller | skipping: Conditional result was False
2025-09-27 00:08:48.423960 | 
2025-09-27 00:08:48.424099 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-27 00:08:48.921556 | controller -> localhost | changed
2025-09-27 00:08:48.932929 | 
2025-09-27 00:08:48.933010 | TASK [add-build-sshkey : Add back temp key]
2025-09-27 00:08:49.222182 | controller -> localhost | Identity added: /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/work/2092fa999a77420687fe9dd02e148ce8_id_rsa (zuul-build-sshkey)
2025-09-27 00:08:49.222515 | controller -> localhost | ok: Runtime: 0:00:00.009011
2025-09-27 00:08:49.236705 | 
2025-09-27 00:08:49.236835 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-27 00:08:49.762623 | controller | ok
2025-09-27 00:08:49.775060 | 
2025-09-27 00:08:49.775241 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-27 00:08:49.812672 | controller | skipping: Conditional result was False
2025-09-27 00:08:49.828336 | 
2025-09-27 00:08:49.828445 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-27 00:08:49.860222 | controller | ok
2025-09-27 00:08:49.882014 | 
2025-09-27 00:08:49.882135 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-27 00:08:50.132106 | controller -> localhost | ok
2025-09-27 00:08:50.139133 | 
2025-09-27 00:08:50.139208 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-27 00:08:50.175864 | controller | ok
2025-09-27 00:08:50.186998 | controller | included: /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-27 00:08:50.193121 | 
2025-09-27 00:08:50.193208 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-27 00:08:50.504707 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-27 00:08:50.504954 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/work/2092fa999a77420687fe9dd02e148ce8_id_ecdsa.
2025-09-27 00:08:50.504999 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/work/2092fa999a77420687fe9dd02e148ce8_id_ecdsa.pub.
2025-09-27 00:08:50.505031 | controller -> localhost | The key fingerprint is:
2025-09-27 00:08:50.505052 | controller -> localhost | SHA256:qlrsw1wPAbBk738Dxgv0qWlBqzqJ4Pklb2dA/i95jfc zuul-build-sshkey
2025-09-27 00:08:50.505071 | controller -> localhost | The key's randomart image is:
2025-09-27 00:08:50.505089 | controller -> localhost | +---[ECDSA 521]---+
2025-09-27 00:08:50.505107 | controller -> localhost | |  +.             |
2025-09-27 00:08:50.505124 | controller -> localhost | | o o.            |
2025-09-27 00:08:50.505141 | controller -> localhost | |  . +.           |
2025-09-27 00:08:50.505158 | controller -> localhost | |   + =..         |
2025-09-27 00:08:50.505175 | controller -> localhost | |    B *.S        |
2025-09-27 00:08:50.505193 | controller -> localhost | |.  o Xo+         |
2025-09-27 00:08:50.505210 | controller -> localhost | |+.o+*o*o+ o      |
2025-09-27 00:08:50.505248 | controller -> localhost | |++ +Bo B.+ o     |
2025-09-27 00:08:50.505266 | controller -> localhost | |..oo+oo +.. .E   |
2025-09-27 00:08:50.505284 | controller -> localhost | +----[SHA256]-----+
2025-09-27 00:08:50.505335 | controller -> localhost | ok: Runtime: 0:00:00.015981
2025-09-27 00:08:50.512135 | 
2025-09-27 00:08:50.512198 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-27 00:08:50.544453 | controller | ok
2025-09-27 00:08:50.551579 | controller | included: /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-27 00:08:50.560593 | 
2025-09-27 00:08:50.560662 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-27 00:08:50.585466 | controller | skipping: Conditional result was False
2025-09-27 00:08:50.594881 | 
2025-09-27 00:08:50.594973 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-27 00:08:51.059492 | controller | changed
2025-09-27 00:08:51.072255 | 
2025-09-27 00:08:51.072442 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-27 00:08:51.416039 | controller | ok
2025-09-27 00:08:51.424165 | 
2025-09-27 00:08:51.424274 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-27 00:08:52.708855 | controller | changed
2025-09-27 00:08:52.721495 | 
2025-09-27 00:08:52.721653 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-27 00:08:53.992162 | controller | changed
2025-09-27 00:08:54.004941 | 
2025-09-27 00:08:54.005112 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-27 00:08:54.035090 | controller | skipping: Conditional result was False
2025-09-27 00:08:54.045906 | 
2025-09-27 00:08:54.046015 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-27 00:08:54.369325 | controller -> localhost | changed
2025-09-27 00:08:54.382153 | 
2025-09-27 00:08:54.382249 | TASK [add-build-sshkey : Add back temp key]
2025-09-27 00:08:54.738768 | controller -> localhost | Identity added: /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/work/2092fa999a77420687fe9dd02e148ce8_id_ecdsa (zuul-build-sshkey)
2025-09-27 00:08:54.738975 | controller -> localhost | ok: Runtime: 0:00:00.006809
2025-09-27 00:08:54.744834 | 
2025-09-27 00:08:54.744954 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-27 00:08:55.098330 | controller | ok
2025-09-27 00:08:55.111844 | 
2025-09-27 00:08:55.112010 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-27 00:08:55.151241 | controller | skipping: Conditional result was False
2025-09-27 00:08:55.178957 | 
2025-09-27 00:08:55.179115 | TASK [include_role : remove-zuul-sshkey]
2025-09-27 00:08:55.207459 | controller | skipping: Conditional result was False
2025-09-27 00:08:55.222418 | 
2025-09-27 00:08:55.222575 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-27 00:08:55.555160 | controller | ok: "logs"
2025-09-27 00:08:55.555638 | controller | ok: All items complete
2025-09-27 00:08:55.555750 | 
2025-09-27 00:08:55.822758 | controller | ok: "artifacts"
2025-09-27 00:08:56.105434 | controller | ok: "docs"
2025-09-27 00:08:56.128797 | 
2025-09-27 00:08:56.129008 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-27 00:08:56.464189 | controller | changed: "logs"
2025-09-27 00:08:56.749830 | controller | changed: "artifacts"
2025-09-27 00:08:57.019917 | controller | changed: "docs"
2025-09-27 00:08:57.078830 | 
2025-09-27 00:08:57.079083 | PLAY RECAP
2025-09-27 00:08:57.079152 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-27 00:08:57.079192 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-27 00:08:57.079220 | 
2025-09-27 00:08:57.202720 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-27 00:08:57.204101 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-27 00:08:57.813133 | 
2025-09-27 00:08:57.813259 | PLAY [all]
2025-09-27 00:08:57.836817 | 
2025-09-27 00:08:57.836918 | TASK [Install binary dependencies]
2025-09-27 00:08:57.906674 | controller | ok
2025-09-27 00:08:57.926251 | 
2025-09-27 00:08:57.926377 | TASK [bindep : Include find tasks]
2025-09-27 00:08:57.955497 | controller | ok
2025-09-27 00:08:57.962863 | controller | included: /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-27 00:08:57.969806 | 
2025-09-27 00:08:57.969877 | TASK [bindep : Look for bindep.txt]
2025-09-27 00:08:58.499209 | controller | ok
2025-09-27 00:08:58.506010 | 
2025-09-27 00:08:58.506117 | TASK [bindep : Define bindep_file fact]
2025-09-27 00:08:58.530717 | controller | skipping: Conditional result was False
2025-09-27 00:08:58.537893 | 
2025-09-27 00:08:58.538023 | TASK [bindep : Look for other-requirements.txt]
2025-09-27 00:08:58.837529 | controller | ok
2025-09-27 00:08:58.843204 | 
2025-09-27 00:08:58.843306 | TASK [bindep : Define bindep_file fact]
2025-09-27 00:08:58.867577 | controller | skipping: Conditional result was False
2025-09-27 00:08:58.874178 | 
2025-09-27 00:08:58.874304 | TASK [bindep : Look for bindep fallback file]
2025-09-27 00:08:58.898939 | controller | skipping: Conditional result was False
2025-09-27 00:08:58.905312 | 
2025-09-27 00:08:58.905400 | TASK [bindep : Define bindep_file fact]
2025-09-27 00:08:58.929827 | controller | skipping: Conditional result was False
2025-09-27 00:08:58.936324 | 
2025-09-27 00:08:58.936407 | TASK [bindep : Include bindep tasks]
2025-09-27 00:08:58.981406 | controller | skipping: Conditional result was False
2025-09-27 00:08:58.998767 | 
2025-09-27 00:08:58.998946 | TASK [bindep : Include install tasks]
2025-09-27 00:08:59.034975 | controller | skipping: Conditional result was False
2025-09-27 00:08:59.045388 | 
2025-09-27 00:08:59.045510 | LOOP [bindep : Include package tasks]
2025-09-27 00:08:59.114966 | 
2025-09-27 00:08:59.115247 | TASK [Run test-setup role]
2025-09-27 00:08:59.138449 | controller | ok
2025-09-27 00:08:59.171708 | 
2025-09-27 00:08:59.171895 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-27 00:08:59.466810 | controller | ok
2025-09-27 00:08:59.488649 | 
2025-09-27 00:08:59.488824 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-27 00:08:59.646021 | controller | skipping: Conditional result was False
2025-09-27 00:08:59.691130 | 
2025-09-27 00:08:59.691353 | PLAY RECAP
2025-09-27 00:08:59.691424 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-27 00:08:59.691454 | 
2025-09-27 00:08:59.902434 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-27 00:08:59.903774 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-27 00:09:00.577642 | 
2025-09-27 00:09:00.577803 | PLAY [controller]
2025-09-27 00:09:00.600436 | 
2025-09-27 00:09:00.600575 | TASK [Create the /root directory]
2025-09-27 00:09:01.353628 | controller | ok
2025-09-27 00:09:01.367955 | 
2025-09-27 00:09:01.368135 | TASK [Install glibc-langpack-en]
2025-09-27 00:09:09.681704 | controller | ok: Nothing to do
2025-09-27 00:09:09.692994 | 
2025-09-27 00:09:09.693160 | TASK [Ensure controller directory exists]
2025-09-27 00:09:10.074960 | controller | changed
2025-09-27 00:09:10.081253 | 
2025-09-27 00:09:10.081341 | TASK [Install container runtime]
2025-09-27 00:09:10.121812 | controller | ok
2025-09-27 00:09:10.164728 | 
2025-09-27 00:09:10.164875 | LOOP [ensure-podman : Find distribution installation]
2025-09-27 00:09:10.204267 | controller | ok: "/var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-27 00:09:10.222362 | controller | included: /var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-27 00:09:10.232800 | 
2025-09-27 00:09:10.232971 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-27 00:10:24.168235 | controller | changed
2025-09-27 00:10:24.180878 | 
2025-09-27 00:10:24.180990 | TASK [ensure-podman : Fetch podman version]
2025-09-27 00:10:24.929136 | controller | Client:       Podman Engine
2025-09-27 00:10:24.929235 | controller | Version:      4.6.2
2025-09-27 00:10:24.929281 | controller | API Version:  4.6.2
2025-09-27 00:10:24.929322 | controller | Go Version:   go1.19.12
2025-09-27 00:10:24.929373 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-27 00:10:24.929413 | controller | OS/Arch:      linux/amd64
2025-09-27 00:10:25.369138 | controller | ok: Runtime: 0:00:00.187044
2025-09-27 00:10:25.376588 | 
2025-09-27 00:10:25.376728 | TASK [ensure-podman : Print podman version installed]
2025-09-27 00:10:25.420469 | Podman version: Client:       Podman Engine
2025-09-27 00:10:25.420881 | Version:      4.6.2
2025-09-27 00:10:25.420925 | API Version:  4.6.2
2025-09-27 00:10:25.420947 | Go Version:   go1.19.12
2025-09-27 00:10:25.420966 | Built:        Mon Aug 28 19:38:31 2023
2025-09-27 00:10:25.420984 | OS/Arch:      linux/amd64
2025-09-27 00:10:25.430250 | 
2025-09-27 00:10:25.430388 | TASK [ensure-podman : Validate podman engine]
2025-09-27 00:10:25.575501 | controller | skipping: Conditional result was False
2025-09-27 00:10:25.582764 | 
2025-09-27 00:10:25.582888 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-27 00:10:25.617733 | controller | skipping: Conditional result was False
2025-09-27 00:10:25.630822 | 
2025-09-27 00:10:25.630969 | TASK [Ensure python3.8 is present]
2025-09-27 00:10:25.659104 | controller | skipping: Conditional result was False
2025-09-27 00:10:25.667045 | 
2025-09-27 00:10:25.667189 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-27 00:10:25.687051 | controller | ok
2025-09-27 00:10:25.710484 | 
2025-09-27 00:10:25.710601 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-27 00:10:29.390829 | controller | ok: Nothing to do
2025-09-27 00:10:29.396598 | 
2025-09-27 00:10:29.396662 | TASK [our-ensure-python : Also install python3-devel]
2025-09-27 00:10:42.649748 | controller | changed
2025-09-27 00:10:42.660870 | 
2025-09-27 00:10:42.660966 | TASK [Run ensure-virtualenv role]
2025-09-27 00:10:42.680171 | controller | ok
2025-09-27 00:10:42.700810 | 
2025-09-27 00:10:42.700921 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-27 00:10:43.095898 | controller | /usr/bin/virtualenv
2025-09-27 00:10:43.343199 | controller | ok: Runtime: 0:00:00.004892
2025-09-27 00:10:43.349185 | 
2025-09-27 00:10:43.349258 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-27 00:10:43.368982 | controller | skipping: Conditional result was False
2025-09-27 00:10:43.369245 | controller | ok: All items complete
2025-09-27 00:10:43.369274 | 
2025-09-27 00:10:43.412492 | 
2025-09-27 00:10:43.412634 | TASK [Find the full path of the Python interpreter]
2025-09-27 00:10:43.834078 | controller | /usr/bin/python3
2025-09-27 00:10:44.043475 | controller | ok
2025-09-27 00:10:44.051179 | 
2025-09-27 00:10:44.051307 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-27 00:10:45.427250 | controller | created virtual environment CPython3.11.0.final.0-64 in 748ms
2025-09-27 00:10:45.482532 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-27 00:10:45.482605 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv)
2025-09-27 00:10:45.482626 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-27 00:10:45.482649 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-27 00:10:45.700786 | controller | changed
2025-09-27 00:10:45.710900 | 
2025-09-27 00:10:45.722371 | TASK [Set selinux package]
2025-09-27 00:10:45.745640 | controller | ok
2025-09-27 00:10:45.753410 | 
2025-09-27 00:10:45.753489 | TASK [Set selinux package (Fedora)]
2025-09-27 00:10:45.796081 | controller | ok
2025-09-27 00:10:45.807559 | 
2025-09-27 00:10:45.807655 | TASK [Install selinux into virtualenv]
2025-09-27 00:10:48.458257 | controller | Collecting selinux-please-lie-to-me
2025-09-27 00:10:48.552617 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-27 00:10:49.082478 | controller | Collecting setuptools<50.0.0
2025-09-27 00:10:49.097283 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-27 00:10:49.236266 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.2 MB/s eta 0:00:00
2025-09-27 00:10:49.390516 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-27 00:10:49.390851 | controller |   Attempting uninstall: setuptools
2025-09-27 00:10:49.395792 | controller |     Found existing installation: setuptools 62.6.0
2025-09-27 00:10:49.508275 | controller |     Uninstalling setuptools-62.6.0:
2025-09-27 00:10:49.523186 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-27 00:10:50.250869 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-27 00:10:50.467033 | controller |
2025-09-27 00:10:50.682276 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-27 00:10:50.682328 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-27 00:10:50.989265 | controller | ok: Runtime: 0:00:04.421670
2025-09-27 00:10:50.999483 | 
2025-09-27 00:10:50.999606 | TASK [Install pytest-forked into virtualenv]
2025-09-27 00:10:52.196769 | controller | Collecting pytest-forked
2025-09-27 00:10:52.286933 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-27 00:10:52.346713 | controller | Collecting py
2025-09-27 00:10:52.366237 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-27 00:10:52.404046 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00
2025-09-27 00:10:52.579472 | controller | Collecting pytest>=3.10
2025-09-27 00:10:52.591438 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-27 00:10:52.652258 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00
2025-09-27 00:10:52.706912 | controller | Collecting iniconfig>=1
2025-09-27 00:10:52.718560 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-27 00:10:52.786535 | controller | Collecting packaging>=20
2025-09-27 00:10:52.798719 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-27 00:10:52.813168 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.2 MB/s eta 0:00:00
2025-09-27 00:10:52.861411 | controller | Collecting pluggy<2,>=1.5
2025-09-27 00:10:52.873251 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-27 00:10:52.948003 | controller | Collecting pygments>=2.7.2
2025-09-27 00:10:52.963217 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-27 00:10:53.083175 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.5 MB/s eta 0:00:00
2025-09-27 00:10:53.215576 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-27 00:10:55.414749 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-09-27 00:10:55.430754 | controller |
2025-09-27 00:10:55.619487 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-27 00:10:55.619533 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-27 00:10:56.156812 | controller | ok: Runtime: 0:00:04.150163
2025-09-27 00:10:56.165919 | 
2025-09-27 00:10:56.166330 | TASK [Update pip]
2025-09-27 00:10:57.408803 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-27 00:10:57.668223 | controller | Collecting pip
2025-09-27 00:10:57.754246 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-27 00:10:57.911277 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.5 MB/s eta 0:00:00
2025-09-27 00:10:58.079891 | controller | Installing collected packages: pip
2025-09-27 00:10:58.080212 | controller |   Attempting uninstall: pip
2025-09-27 00:10:58.086042 | controller |     Found existing installation: pip 22.2.2
2025-09-27 00:10:58.358949 | controller |     Uninstalling pip-22.2.2:
2025-09-27 00:10:58.388595 | controller |       Successfully uninstalled pip-22.2.2
2025-09-27 00:11:00.095395 | controller | Successfully installed pip-25.2
2025-09-27 00:11:00.819030 | controller | ok: Runtime: 0:00:03.560458
2025-09-27 00:11:00.826821 | 
2025-09-27 00:11:00.826917 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-27 00:11:01.329961 | controller | changed
2025-09-27 00:11:01.337831 | 
2025-09-27 00:11:01.337940 | TASK [Install ansible into virtualenv]
2025-09-27 00:11:02.433925 | controller | Processing ./src/github.com/ansible/ansible
2025-09-27 00:11:02.440555 | controller |   Installing build dependencies: started
2025-09-27 00:11:04.308633 | controller |   Installing build dependencies: finished with status 'done'
2025-09-27 00:11:04.309809 | controller |   Getting requirements to build wheel: started
2025-09-27 00:11:05.844636 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-27 00:11:05.846659 | controller |   Preparing metadata (pyproject.toml): started
2025-09-27 00:11:06.770642 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-27 00:11:06.773105 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-09-27 00:11:06.777906 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-27 00:11:07.004783 | controller | ERROR
2025-09-27 00:11:07.005023 | controller | {
2025-09-27 00:11:07.005329 | controller |   "delta": "0:00:05.132941",
2025-09-27 00:11:07.005391 | controller |   "end": "2025-09-27 00:11:06.927180",
2025-09-27 00:11:07.005444 | controller |   "msg": "non-zero return code",
2025-09-27 00:11:07.005501 | controller |   "rc": 1,
2025-09-27 00:11:07.005541 | controller |   "start": "2025-09-27 00:11:01.794239"
2025-09-27 00:11:07.005582 | controller | }
failure
2025-09-27 00:11:07.008356 | 
2025-09-27 00:11:07.008451 | PLAY RECAP
2025-09-27 00:11:07.008539 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-27 00:11:07.008582 | 
2025-09-27 00:11:07.137402 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-27 00:11:07.140042 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-27 00:11:07.773340 | 
2025-09-27 00:11:07.773476 | PLAY [all]
2025-09-27 00:11:07.797044 | 
2025-09-27 00:11:07.797179 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-27 00:11:08.565900 | controller | changed: non-zero return code
2025-09-27 00:11:08.573559 | 
2025-09-27 00:11:08.573674 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-27 00:11:08.599296 | controller | skipping: Conditional result was False
2025-09-27 00:11:08.607191 | 
2025-09-27 00:11:08.607324 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-27 00:11:08.641746 | 
2025-09-27 00:11:08.641923 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-27 00:11:08.675788 | 
2025-09-27 00:11:08.675998 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-27 00:11:08.692939 | controller | skipping: Conditional result was False
2025-09-27 00:11:08.701813 | 
2025-09-27 00:11:08.701985 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-27 00:11:08.740056 | 
2025-09-27 00:11:08.740266 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-27 00:11:08.755094 | controller | skipping: Conditional result was False
2025-09-27 00:11:08.761835 | 
2025-09-27 00:11:08.761924 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-27 00:11:08.776665 | controller | skipping: Conditional result was False
2025-09-27 00:11:08.783873 | 
2025-09-27 00:11:08.783964 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-27 00:11:08.797883 | controller | skipping: Conditional result was False
2025-09-27 00:11:08.827086 | 
2025-09-27 00:11:08.827210 | PLAY RECAP
2025-09-27 00:11:08.827266 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-27 00:11:08.827289 | 
2025-09-27 00:11:08.960171 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-27 00:11:08.961311 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-27 00:11:09.590992 | 
2025-09-27 00:11:09.591116 | PLAY [all:!appliance*]
2025-09-27 00:11:09.614355 | 
2025-09-27 00:11:09.614522 | TASK [unregister the node]
2025-09-27 00:11:09.751766 | controller | skipping: Conditional result was False
2025-09-27 00:11:09.758041 | 
2025-09-27 00:11:09.758136 | TASK [include_role : fetch-output]
2025-09-27 00:11:09.800397 | controller | ok
2025-09-27 00:11:09.825793 | 
2025-09-27 00:11:09.825913 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-27 00:11:09.911500 | controller | skipping: Conditional result was False
2025-09-27 00:11:09.918284 | 
2025-09-27 00:11:09.918376 | TASK [fetch-output : Set log path for single node]
2025-09-27 00:11:09.967265 | controller | ok
2025-09-27 00:11:09.973525 | 
2025-09-27 00:11:09.973622 | LOOP [fetch-output : Ensure local output dirs]
2025-09-27 00:11:10.411974 | controller -> localhost | ok: "/var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/work/logs"
2025-09-27 00:11:10.668180 | controller -> localhost | changed: "/var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/work/artifacts"
2025-09-27 00:11:10.890569 | controller -> localhost | changed: "/var/lib/zuul/builds/2092fa999a77420687fe9dd02e148ce8/work/docs"
2025-09-27 00:11:10.910563 | 
2025-09-27 00:11:10.910771 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-27 00:11:12.139428 | controller | changed:
2025-09-27 00:11:12.139627 | controller | .d..t...... ./
2025-09-27 00:11:12.139655 | controller | cd+++++++++ controller/
2025-09-27 00:11:12.139719 | controller | changed: All items complete
2025-09-27 00:11:12.139745 | 
2025-09-27 00:11:13.200082 | controller | changed: .d..t...... ./
2025-09-27 00:11:14.226730 | controller | changed: .d..t...... ./
2025-09-27 00:11:14.245292 | 
2025-09-27 00:11:14.245408 | TASK [include_role : fetch-output-openshift]
2025-09-27 00:11:14.260213 | controller | skipping: Conditional result was False
2025-09-27 00:11:14.266895 | 
2025-09-27 00:11:14.266977 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-27 00:11:14.292729 | controller | skipping: Conditional result was False
2025-09-27 00:11:14.301023 | controller | skipping: Conditional result was False
2025-09-27 00:11:14.335889 | 
2025-09-27 00:11:14.336038 | PLAY [localhost]
2025-09-27 00:11:14.358054 | 
2025-09-27 00:11:14.358186 | TASK [Run Zuul manifest role]
2025-09-27 00:11:14.378208 | localhost | ok
2025-09-27 00:11:14.394431 | 
2025-09-27 00:11:14.394551 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-27 00:11:14.804025 | localhost | changed
2025-09-27 00:11:14.808933 | 
2025-09-27 00:11:14.809013 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-27 00:11:14.838856 | localhost | ok
2025-09-27 00:11:14.849484 | 
2025-09-27 00:11:14.849606 | TASK [Set zuul-log-path fact]
2025-09-27 00:11:14.869193 | localhost | ok
2025-09-27 00:11:14.890796 | 
2025-09-27 00:11:14.890956 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-27 00:11:14.921020 | localhost | ok
2025-09-27 00:11:14.935427 | 
2025-09-27 00:11:14.935568 | LOOP [Run upload-logs-swift role]
2025-09-27 00:11:14.971296 | localhost | Output suppressed because no_log was given
2025-09-27 00:11:15.020244 | 
2025-09-27 00:11:15.020399 | TASK [Set zuul-log-path fact]
2025-09-27 00:11:15.047002 | localhost | skipping: Conditional result was False
2025-09-27 00:11:15.054872 | 
2025-09-27 00:11:15.054980 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-27 00:11:15.563099 | localhost -> localhost | ok: Runtime: 0:00:00.006271
2025-09-27 00:11:15.576069 | 
2025-09-27 00:11:15.576216 | TASK [upload-logs-swift : Upload logs to swift]