2025-09-17 00:16:55.546534 | Job console starting...
2025-09-17 00:16:55.556887 | Updating repositories
2025-09-17 00:16:55.686713 | Preparing job workspace
2025-09-17 00:16:59.627970 | Running Ansible setup...
2025-09-17 00:17:07.297054 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-17 00:17:07.900686 | 
2025-09-17 00:17:07.900801 | PLAY [localhost]
2025-09-17 00:17:07.909100 | 
2025-09-17 00:17:07.909169 | TASK [Gathering Facts]
2025-09-17 00:17:08.936548 | localhost | ok
2025-09-17 00:17:08.970553 | 
2025-09-17 00:17:08.970843 | TASK [Setup log path fact]
2025-09-17 00:17:08.993870 | localhost | ok
2025-09-17 00:17:09.010956 | 
2025-09-17 00:17:09.011047 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-17 00:17:09.040727 | localhost | ok
2025-09-17 00:17:09.051566 | 
2025-09-17 00:17:09.051687 | TASK [emit-job-header : Print job information]
2025-09-17 00:17:09.101379 | # Job Information
2025-09-17 00:17:09.101527 | Ansible Version: 2.15.12
2025-09-17 00:17:09.101568 | Job: ansible-test-sanity-docker-milestone
2025-09-17 00:17:09.101596 | Pipeline: periodic
2025-09-17 00:17:09.101622 | Executor: ze02.softwarefactory-project.io
2025-09-17 00:17:09.101647 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-17 00:17:09.101699 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/fe7/ansible/fe78ee35bb4e497fb3d7f1eb05af6c9a/
2025-09-17 00:17:09.101728 | Event ID: eca5199f70dd4f21ae7c1e30717f8aa4
2025-09-17 00:17:09.106777 | 
2025-09-17 00:17:09.106861 | LOOP [emit-job-header : Print node information]
2025-09-17 00:17:09.220589 | localhost | ok:
2025-09-17 00:17:09.220964 | localhost | # Node Information
2025-09-17 00:17:09.221024 | localhost | Inventory Hostname: controller
2025-09-17 00:17:09.221066 | localhost | Hostname: ip-172-16-204-36
2025-09-17 00:17:09.221126 | localhost | Username: zuul-worker
2025-09-17 00:17:09.221178 | localhost | Distro: Fedora 37
2025-09-17 00:17:09.221219 | localhost | Provider: ansible-us-east-2
2025-09-17 00:17:09.221257 | localhost | Region: us-east-2
2025-09-17 00:17:09.221294 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-17 00:17:09.221331 | localhost | Product Name: t3.small
2025-09-17 00:17:09.221368 | localhost | Interface IP: 3.140.238.62
2025-09-17 00:17:09.235117 | 
2025-09-17 00:17:09.235297 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-17 00:17:09.636319 | localhost -> localhost | changed
2025-09-17 00:17:09.650170 | 
2025-09-17 00:17:09.650325 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-17 00:17:10.488594 | localhost -> localhost | changed
2025-09-17 00:17:10.531703 | 
2025-09-17 00:17:10.531810 | PLAY [all:!appliance*]
2025-09-17 00:17:10.554092 | 
2025-09-17 00:17:10.554187 | TASK [include_role : start-zuul-console]
2025-09-17 00:17:10.586338 | controller | ok
2025-09-17 00:17:10.604476 | 
2025-09-17 00:17:10.604590 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-17 00:17:11.261861 | controller | ok
2025-09-17 00:17:11.284785 | 
2025-09-17 00:17:11.284931 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-17 00:17:13.126880 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-17 00:17:13.133484 | 
2025-09-17 00:17:13.133550 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-17 00:17:13.260782 | controller | skipping: Conditional result was False
2025-09-17 00:17:13.276275 | 
2025-09-17 00:17:13.276456 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-17 00:17:13.309366 | controller | skipping: Conditional result was False
2025-09-17 00:17:13.324683 | 
2025-09-17 00:17:13.324790 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-17 00:17:13.350644 | controller | skipping: Conditional result was False
2025-09-17 00:17:13.359327 | 
2025-09-17 00:17:13.359418 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-17 00:17:13.384153 | controller | skipping: Conditional result was False
2025-09-17 00:17:13.392961 | 
2025-09-17 00:17:13.393064 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-17 00:17:13.417532 | controller | skipping: Conditional result was False
2025-09-17 00:17:13.425562 | 
2025-09-17 00:17:13.425653 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-17 00:17:13.450535 | controller | skipping: Conditional result was False
2025-09-17 00:17:13.467324 | 
2025-09-17 00:17:13.467409 | TASK [Disable Fedora Modular]
2025-09-17 00:17:14.215300 | controller | changed
2025-09-17 00:17:14.230648 | 
2025-09-17 00:17:14.230827 | TASK [Enable EPEL]
2025-09-17 00:17:14.259086 | controller | skipping: Conditional result was False
2025-09-17 00:17:14.272739 | 
2025-09-17 00:17:14.272895 | TASK [Register the RHEL node]
2025-09-17 00:17:14.431736 | 
2025-09-17 00:17:14.431923 | TASK [Show the subscription-manager status]
2025-09-17 00:17:14.589566 | controller | skipping: Conditional result was False
2025-09-17 00:17:14.596613 | 
2025-09-17 00:17:14.596695 | TASK [Enable EPEL on RHEL]
2025-09-17 00:17:14.719574 | controller | skipping: Conditional result was False
2025-09-17 00:17:14.725903 | 
2025-09-17 00:17:14.725993 | TASK [Install git and tox]
2025-09-17 00:18:47.137455 | controller | changed
2025-09-17 00:18:47.151364 | 
2025-09-17 00:18:47.151530 | TASK [include_role : prepare-workspace]
2025-09-17 00:18:47.199845 | controller | ok
2025-09-17 00:18:47.238109 | 
2025-09-17 00:18:47.238234 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-17 00:18:47.763591 | controller | ok
2025-09-17 00:18:47.777595 | 
2025-09-17 00:18:47.777764 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-17 00:19:00.154253 | controller | Output suppressed because no_log was given
2025-09-17 00:19:00.168704 | 
2025-09-17 00:19:00.168791 | TASK [include_role : prepare-workspace-openshift]
2025-09-17 00:19:00.196047 | controller | skipping: Conditional result was False
2025-09-17 00:19:00.226125 | 
2025-09-17 00:19:00.226206 | PLAY [all:!appliance]
2025-09-17 00:19:00.248506 | 
2025-09-17 00:19:00.248590 | TASK [Run add-build-sshkey role (RSA)]
2025-09-17 00:19:00.324315 | controller | ok
2025-09-17 00:19:00.339412 | 
2025-09-17 00:19:00.339483 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-17 00:19:00.628758 | controller -> localhost | ok
2025-09-17 00:19:00.642460 | 
2025-09-17 00:19:00.642599 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-17 00:19:00.691761 | controller | ok
2025-09-17 00:19:00.724624 | controller | included: /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-17 00:19:00.732446 | 
2025-09-17 00:19:00.732531 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-17 00:19:01.327527 | controller -> localhost | Generating public/private rsa key pair.
2025-09-17 00:19:01.327950 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/work/fe78ee35bb4e497fb3d7f1eb05af6c9a_id_rsa.
2025-09-17 00:19:01.328016 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/work/fe78ee35bb4e497fb3d7f1eb05af6c9a_id_rsa.pub.
2025-09-17 00:19:01.328062 | controller -> localhost | The key fingerprint is:
2025-09-17 00:19:01.328104 | controller -> localhost | SHA256:ECW2ynUco3Cq6TTfjqWvRlNqzekVjpH8DEyropZ5mGY zuul-build-sshkey
2025-09-17 00:19:01.328144 | controller -> localhost | The key's randomart image is:
2025-09-17 00:19:01.328184 | controller -> localhost | +---[RSA 2048]----+
2025-09-17 00:19:01.328222 | controller -> localhost | |    . =.+        |
2025-09-17 00:19:01.328262 | controller -> localhost | |     =.* o       |
2025-09-17 00:19:01.328301 | controller -> localhost | |    .+=oo        |
2025-09-17 00:19:01.328340 | controller -> localhost | |   + oOo.        |
2025-09-17 00:19:01.328378 | controller -> localhost | |  = o* OS.       |
2025-09-17 00:19:01.328433 | controller -> localhost | | o.o*.= =        |
2025-09-17 00:19:01.328483 | controller -> localhost | | .*+.oo.         |
2025-09-17 00:19:01.328524 | controller -> localhost | |.E ..=.          |
2025-09-17 00:19:01.328564 | controller -> localhost | |+ ..+oo          |
2025-09-17 00:19:01.328607 | controller -> localhost | +----[SHA256]-----+
2025-09-17 00:19:01.328732 | controller -> localhost | ok: Runtime: 0:00:00.126549
2025-09-17 00:19:01.342182 | 
2025-09-17 00:19:01.342312 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-17 00:19:01.381063 | controller | ok
2025-09-17 00:19:01.400888 | controller | included: /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-17 00:19:01.412855 | 
2025-09-17 00:19:01.412947 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-17 00:19:01.437840 | controller | skipping: Conditional result was False
2025-09-17 00:19:01.447516 | 
2025-09-17 00:19:01.447602 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-17 00:19:03.326802 | controller | changed
2025-09-17 00:19:03.334324 | 
2025-09-17 00:19:03.334410 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-17 00:19:04.027650 | controller | ok
2025-09-17 00:19:04.040174 | 
2025-09-17 00:19:04.040315 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-17 00:19:05.490119 | controller | changed
2025-09-17 00:19:05.505366 | 
2025-09-17 00:19:05.505524 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-17 00:19:06.773791 | controller | changed
2025-09-17 00:19:06.787033 | 
2025-09-17 00:19:06.787175 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-17 00:19:06.815245 | controller | skipping: Conditional result was False
2025-09-17 00:19:06.831359 | 
2025-09-17 00:19:06.831555 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-17 00:19:07.329131 | controller -> localhost | changed
2025-09-17 00:19:07.354707 | 
2025-09-17 00:19:07.354885 | TASK [add-build-sshkey : Add back temp key]
2025-09-17 00:19:07.678333 | controller -> localhost | Identity added: /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/work/fe78ee35bb4e497fb3d7f1eb05af6c9a_id_rsa (zuul-build-sshkey)
2025-09-17 00:19:07.678648 | controller -> localhost | ok: Runtime: 0:00:00.012902
2025-09-17 00:19:07.691442 | 
2025-09-17 00:19:07.691588 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-17 00:19:08.241718 | controller | ok
2025-09-17 00:19:08.259637 | 
2025-09-17 00:19:08.259896 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-17 00:19:08.299184 | controller | skipping: Conditional result was False
2025-09-17 00:19:08.327243 | 
2025-09-17 00:19:08.327428 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-17 00:19:08.368978 | controller | ok
2025-09-17 00:19:08.399193 | 
2025-09-17 00:19:08.399312 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-17 00:19:08.678398 | controller -> localhost | ok
2025-09-17 00:19:08.684632 | 
2025-09-17 00:19:08.684713 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-17 00:19:08.715713 | controller | ok
2025-09-17 00:19:08.728980 | controller | included: /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-17 00:19:08.738364 | 
2025-09-17 00:19:08.738534 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-17 00:19:09.008267 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-17 00:19:09.008481 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/work/fe78ee35bb4e497fb3d7f1eb05af6c9a_id_ecdsa.
2025-09-17 00:19:09.008510 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/work/fe78ee35bb4e497fb3d7f1eb05af6c9a_id_ecdsa.pub.
2025-09-17 00:19:09.008540 | controller -> localhost | The key fingerprint is:
2025-09-17 00:19:09.008560 | controller -> localhost | SHA256:BxilX7qsEDKfOKJXi+2MOk/jzF2Yo8bCWADs0w4dVVI zuul-build-sshkey
2025-09-17 00:19:09.008579 | controller -> localhost | The key's randomart image is:
2025-09-17 00:19:09.008597 | controller -> localhost | +---[ECDSA 521]---+
2025-09-17 00:19:09.008615 | controller -> localhost | |.   .o+E.        |
2025-09-17 00:19:09.008633 | controller -> localhost | |.. .  .+         |
2025-09-17 00:19:09.008650 | controller -> localhost | |o o . o . .      |
2025-09-17 00:19:09.008757 | controller -> localhost | |.+ o   . +       |
2025-09-17 00:19:09.008778 | controller -> localhost | | .* .   S .      |
2025-09-17 00:19:09.008796 | controller -> localhost | |  .*.= . o       |
2025-09-17 00:19:09.008813 | controller -> localhost | |+o=+B.. o        |
2025-09-17 00:19:09.008830 | controller -> localhost | |=B=Bo+ .         |
2025-09-17 00:19:09.008847 | controller -> localhost | |oBB.+ .          |
2025-09-17 00:19:09.008865 | controller -> localhost | +----[SHA256]-----+
2025-09-17 00:19:09.008906 | controller -> localhost | ok: Runtime: 0:00:00.014309
2025-09-17 00:19:09.015987 | 
2025-09-17 00:19:09.016058 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-17 00:19:09.055933 | controller | ok
2025-09-17 00:19:09.063520 | controller | included: /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-17 00:19:09.072190 | 
2025-09-17 00:19:09.072262 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-17 00:19:09.097048 | controller | skipping: Conditional result was False
2025-09-17 00:19:09.104325 | 
2025-09-17 00:19:09.104400 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-17 00:19:09.572349 | controller | changed
2025-09-17 00:19:09.577762 | 
2025-09-17 00:19:09.577831 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-17 00:19:09.926864 | controller | ok
2025-09-17 00:19:09.932181 | 
2025-09-17 00:19:09.932244 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-17 00:19:11.626332 | controller | changed
2025-09-17 00:19:11.640054 | 
2025-09-17 00:19:11.640323 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-17 00:19:12.961290 | controller | changed
2025-09-17 00:19:12.975197 | 
2025-09-17 00:19:12.975341 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-17 00:19:13.014747 | controller | skipping: Conditional result was False
2025-09-17 00:19:13.030959 | 
2025-09-17 00:19:13.031111 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-17 00:19:13.427512 | controller -> localhost | changed
2025-09-17 00:19:13.440034 | 
2025-09-17 00:19:13.440136 | TASK [add-build-sshkey : Add back temp key]
2025-09-17 00:19:13.719293 | controller -> localhost | Identity added: /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/work/fe78ee35bb4e497fb3d7f1eb05af6c9a_id_ecdsa (zuul-build-sshkey)
2025-09-17 00:19:13.719512 | controller -> localhost | ok: Runtime: 0:00:00.011548
2025-09-17 00:19:13.726739 | 
2025-09-17 00:19:13.726805 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-17 00:19:14.131820 | controller | ok
2025-09-17 00:19:14.138866 | 
2025-09-17 00:19:14.138948 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-17 00:19:14.173864 | controller | skipping: Conditional result was False
2025-09-17 00:19:14.185121 | 
2025-09-17 00:19:14.185187 | TASK [include_role : remove-zuul-sshkey]
2025-09-17 00:19:14.209349 | controller | skipping: Conditional result was False
2025-09-17 00:19:14.215156 | 
2025-09-17 00:19:14.215219 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-17 00:19:14.536660 | controller | ok: "logs"
2025-09-17 00:19:14.536972 | controller | ok: All items complete
2025-09-17 00:19:14.537001 | 
2025-09-17 00:19:14.824159 | controller | ok: "artifacts"
2025-09-17 00:19:15.136778 | controller | ok: "docs"
2025-09-17 00:19:15.153893 | 
2025-09-17 00:19:15.154017 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-17 00:19:15.493079 | controller | changed: "logs"
2025-09-17 00:19:15.797178 | controller | changed: "artifacts"
2025-09-17 00:19:16.083227 | controller | changed: "docs"
2025-09-17 00:19:16.135847 | 
2025-09-17 00:19:16.136072 | PLAY RECAP
2025-09-17 00:19:16.136224 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-17 00:19:16.136279 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-17 00:19:16.136309 | 
2025-09-17 00:19:16.264394 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-17 00:19:16.265706 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-17 00:19:16.885848 | 
2025-09-17 00:19:16.885952 | PLAY [all]
2025-09-17 00:19:16.907603 | 
2025-09-17 00:19:16.907721 | TASK [Install binary dependencies]
2025-09-17 00:19:16.958970 | controller | ok
2025-09-17 00:19:16.982189 | 
2025-09-17 00:19:16.982381 | TASK [bindep : Include find tasks]
2025-09-17 00:19:17.018845 | controller | ok
2025-09-17 00:19:17.029842 | controller | included: /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-17 00:19:17.039102 | 
2025-09-17 00:19:17.039208 | TASK [bindep : Look for bindep.txt]
2025-09-17 00:19:17.567254 | controller | ok
2025-09-17 00:19:17.583395 | 
2025-09-17 00:19:17.584009 | TASK [bindep : Define bindep_file fact]
2025-09-17 00:19:17.612843 | controller | skipping: Conditional result was False
2025-09-17 00:19:17.627118 | 
2025-09-17 00:19:17.627290 | TASK [bindep : Look for other-requirements.txt]
2025-09-17 00:19:17.934752 | controller | ok
2025-09-17 00:19:17.940258 | 
2025-09-17 00:19:17.940344 | TASK [bindep : Define bindep_file fact]
2025-09-17 00:19:17.964322 | controller | skipping: Conditional result was False
2025-09-17 00:19:17.971410 | 
2025-09-17 00:19:17.971491 | TASK [bindep : Look for bindep fallback file]
2025-09-17 00:19:17.996155 | controller | skipping: Conditional result was False
2025-09-17 00:19:18.001932 | 
2025-09-17 00:19:18.002012 | TASK [bindep : Define bindep_file fact]
2025-09-17 00:19:18.026251 | controller | skipping: Conditional result was False
2025-09-17 00:19:18.033526 | 
2025-09-17 00:19:18.033597 | TASK [bindep : Include bindep tasks]
2025-09-17 00:19:18.058361 | controller | skipping: Conditional result was False
2025-09-17 00:19:18.066112 | 
2025-09-17 00:19:18.066229 | TASK [bindep : Include install tasks]
2025-09-17 00:19:18.090583 | controller | skipping: Conditional result was False
2025-09-17 00:19:18.097736 | 
2025-09-17 00:19:18.097813 | LOOP [bindep : Include package tasks]
2025-09-17 00:19:18.154241 | 
2025-09-17 00:19:18.154403 | TASK [Run test-setup role]
2025-09-17 00:19:18.173947 | controller | ok
2025-09-17 00:19:18.192054 | 
2025-09-17 00:19:18.192154 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-17 00:19:18.479204 | controller | ok
2025-09-17 00:19:18.498808 | 
2025-09-17 00:19:18.499225 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-17 00:19:18.662106 | controller | skipping: Conditional result was False
2025-09-17 00:19:18.715849 | 
2025-09-17 00:19:18.715979 | PLAY RECAP
2025-09-17 00:19:18.716031 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-17 00:19:18.716058 | 
2025-09-17 00:19:18.875270 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-17 00:19:18.876132 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-17 00:19:19.499085 | 
2025-09-17 00:19:19.499225 | PLAY [controller]
2025-09-17 00:19:19.524466 | 
2025-09-17 00:19:19.524582 | TASK [Create the /root directory]
2025-09-17 00:19:20.220830 | controller | ok
2025-09-17 00:19:20.245186 | 
2025-09-17 00:19:20.245480 | TASK [Install glibc-langpack-en]
2025-09-17 00:19:27.843449 | controller | ok: Nothing to do
2025-09-17 00:19:27.858246 | 
2025-09-17 00:19:27.858391 | TASK [Ensure controller directory exists]
2025-09-17 00:19:28.379079 | controller | changed
2025-09-17 00:19:28.391827 | 
2025-09-17 00:19:28.391973 | TASK [Install container runtime]
2025-09-17 00:19:28.499589 | controller | ok
2025-09-17 00:19:28.554134 | 
2025-09-17 00:19:28.554299 | LOOP [ensure-podman : Find distribution installation]
2025-09-17 00:19:28.596961 | controller | ok: "/var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-17 00:19:28.612042 | controller | included: /var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-17 00:19:28.619418 | 
2025-09-17 00:19:28.619511 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-17 00:20:44.871214 | controller | changed
2025-09-17 00:20:44.877610 | 
2025-09-17 00:20:44.877699 | TASK [ensure-podman : Fetch podman version]
2025-09-17 00:20:45.650638 | controller | Client:       Podman Engine
2025-09-17 00:20:45.677384 | controller | Version:      4.6.2
2025-09-17 00:20:45.677430 | controller | API Version:  4.6.2
2025-09-17 00:20:45.677507 | controller | Go Version:   go1.19.12
2025-09-17 00:20:45.677529 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-17 00:20:45.677550 | controller | OS/Arch:      linux/amd64
2025-09-17 00:20:46.004171 | controller | ok: Runtime: 0:00:00.229488
2025-09-17 00:20:46.011127 | 
2025-09-17 00:20:46.011204 | TASK [ensure-podman : Print podman version installed]
2025-09-17 00:20:46.054525 | Podman version: Client:       Podman Engine
2025-09-17 00:20:46.054795 | Version:      4.6.2
2025-09-17 00:20:46.054826 | API Version:  4.6.2
2025-09-17 00:20:46.054845 | Go Version:   go1.19.12
2025-09-17 00:20:46.054863 | Built:        Mon Aug 28 19:38:31 2023
2025-09-17 00:20:46.054882 | OS/Arch:      linux/amd64
2025-09-17 00:20:46.061029 | 
2025-09-17 00:20:46.061097 | TASK [ensure-podman : Validate podman engine]
2025-09-17 00:20:46.188116 | controller | skipping: Conditional result was False
2025-09-17 00:20:46.201486 | 
2025-09-17 00:20:46.201629 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-17 00:20:46.230420 | controller | skipping: Conditional result was False
2025-09-17 00:20:46.246479 | 
2025-09-17 00:20:46.246574 | TASK [Ensure python3.8 is present]
2025-09-17 00:20:46.274882 | controller | skipping: Conditional result was False
2025-09-17 00:20:46.281795 | 
2025-09-17 00:20:46.281861 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-17 00:20:46.312322 | controller | ok
2025-09-17 00:20:46.331307 | 
2025-09-17 00:20:46.331384 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-17 00:20:50.283410 | controller | ok: Nothing to do
2025-09-17 00:20:50.295030 | 
2025-09-17 00:20:50.295173 | TASK [our-ensure-python : Also install python3-devel]
2025-09-17 00:21:04.783834 | controller | changed
2025-09-17 00:21:04.806249 | 
2025-09-17 00:21:04.806359 | TASK [Run ensure-virtualenv role]
2025-09-17 00:21:04.831281 | controller | ok
2025-09-17 00:21:04.863427 | 
2025-09-17 00:21:04.863542 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-17 00:21:05.220966 | controller | /usr/bin/virtualenv
2025-09-17 00:21:05.493952 | controller | ok: Runtime: 0:00:00.004530
2025-09-17 00:21:05.503009 | 
2025-09-17 00:21:05.503126 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-17 00:21:05.529179 | controller | skipping: Conditional result was False
2025-09-17 00:21:05.529463 | controller | ok: All items complete
2025-09-17 00:21:05.529492 | 
2025-09-17 00:21:05.571931 | 
2025-09-17 00:21:05.572146 | TASK [Find the full path of the Python interpreter]
2025-09-17 00:21:06.029829 | controller | /usr/bin/python3
2025-09-17 00:21:06.247293 | controller | ok
2025-09-17 00:21:06.259782 | 
2025-09-17 00:21:06.259988 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-17 00:21:07.697023 | controller | created virtual environment CPython3.11.0.final.0-64 in 728ms
2025-09-17 00:21:07.765240 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-17 00:21:07.765974 | 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-17 00:21:07.766001 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-17 00:21:07.766025 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-17 00:21:07.903220 | controller | changed
2025-09-17 00:21:07.911141 | 
2025-09-17 00:21:07.911227 | TASK [Set selinux package]
2025-09-17 00:21:07.944984 | controller | ok
2025-09-17 00:21:07.950406 | 
2025-09-17 00:21:07.950478 | TASK [Set selinux package (Fedora)]
2025-09-17 00:21:08.011941 | controller | ok
2025-09-17 00:21:08.023348 | 
2025-09-17 00:21:08.023481 | TASK [Install selinux into virtualenv]
2025-09-17 00:21:10.669094 | controller | Collecting selinux-please-lie-to-me
2025-09-17 00:21:10.755980 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-17 00:21:11.282447 | controller | Collecting setuptools<50.0.0
2025-09-17 00:21:11.295979 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-17 00:21:11.438809 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 5.9 MB/s eta 0:00:00
2025-09-17 00:21:11.593360 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-17 00:21:11.593804 | controller |   Attempting uninstall: setuptools
2025-09-17 00:21:11.598748 | controller |     Found existing installation: setuptools 62.6.0
2025-09-17 00:21:11.711619 | controller |     Uninstalling setuptools-62.6.0:
2025-09-17 00:21:11.727067 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-17 00:21:12.454207 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-17 00:21:12.660277 | controller |
2025-09-17 00:21:12.877627 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-17 00:21:12.877680 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-17 00:21:13.213097 | controller | ok: Runtime: 0:00:04.365240
2025-09-17 00:21:13.227333 | 
2025-09-17 00:21:13.227699 | TASK [Install pytest-forked into virtualenv]
2025-09-17 00:21:14.499932 | controller | Collecting pytest-forked
2025-09-17 00:21:14.588952 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-17 00:21:14.645045 | controller | Collecting py
2025-09-17 00:21:14.658053 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-17 00:21:14.695127 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-09-17 00:21:14.869182 | controller | Collecting pytest>=3.10
2025-09-17 00:21:14.882704 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-17 00:21:14.947616 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.9 MB/s eta 0:00:00
2025-09-17 00:21:15.000726 | controller | Collecting iniconfig>=1
2025-09-17 00:21:15.014424 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-17 00:21:15.081162 | controller | Collecting packaging>=20
2025-09-17 00:21:15.094507 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-17 00:21:15.107058 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.6 MB/s eta 0:00:00
2025-09-17 00:21:15.151438 | controller | Collecting pluggy<2,>=1.5
2025-09-17 00:21:15.165871 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-17 00:21:15.241702 | controller | Collecting pygments>=2.7.2
2025-09-17 00:21:15.254065 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-17 00:21:15.400653 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 8.5 MB/s eta 0:00:00
2025-09-17 00:21:15.531131 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-17 00:21:17.781206 | 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-17 00:21:17.797376 | controller |
2025-09-17 00:21:17.987135 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-17 00:21:17.987181 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-17 00:21:18.431097 | controller | ok: Runtime: 0:00:04.228956
2025-09-17 00:21:18.444624 | 
2025-09-17 00:21:18.444794 | TASK [Update pip]
2025-09-17 00:21:19.640564 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-17 00:21:19.919722 | controller | Collecting pip
2025-09-17 00:21:20.024365 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-17 00:21:20.204002 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.1 MB/s eta 0:00:00
2025-09-17 00:21:20.365660 | controller | Installing collected packages: pip
2025-09-17 00:21:20.365956 | controller |   Attempting uninstall: pip
2025-09-17 00:21:20.371815 | controller |     Found existing installation: pip 22.2.2
2025-09-17 00:21:20.687577 | controller |     Uninstalling pip-22.2.2:
2025-09-17 00:21:20.717137 | controller |       Successfully uninstalled pip-22.2.2
2025-09-17 00:21:22.461850 | controller | Successfully installed pip-25.2
2025-09-17 00:21:23.116048 | controller | ok: Runtime: 0:00:03.657380
2025-09-17 00:21:23.123204 | 
2025-09-17 00:21:23.123280 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-17 00:21:23.674921 | controller | changed
2025-09-17 00:21:23.690623 | 
2025-09-17 00:21:23.690877 | TASK [Install ansible into virtualenv]
2025-09-17 00:21:24.842639 | controller | Processing ./src/github.com/ansible/ansible
2025-09-17 00:21:24.849167 | controller |   Installing build dependencies: started
2025-09-17 00:21:26.754989 | controller |   Installing build dependencies: finished with status 'done'
2025-09-17 00:21:28.240603 | controller |   Getting requirements to build wheel: started
2025-09-17 00:21:28.240668 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-17 00:21:28.240827 | controller |   Preparing metadata (pyproject.toml): started
2025-09-17 00:21:29.158609 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-17 00:21:29.163394 | 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-17 00:21:29.168212 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-17 00:21:29.846159 | controller | ERROR
2025-09-17 00:21:29.846584 | controller | {
2025-09-17 00:21:29.846647 | controller |   "delta": "0:00:05.129303",
2025-09-17 00:21:29.846749 | controller |   "end": "2025-09-17 00:21:29.315383",
2025-09-17 00:21:29.846791 | controller |   "msg": "non-zero return code",
2025-09-17 00:21:29.846853 | controller |   "rc": 1,
2025-09-17 00:21:29.846890 | controller |   "start": "2025-09-17 00:21:24.186080"
2025-09-17 00:21:29.846924 | controller | }
failure
2025-09-17 00:21:29.850187 | 
2025-09-17 00:21:29.850295 | PLAY RECAP
2025-09-17 00:21:29.850386 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-17 00:21:29.850431 | 
2025-09-17 00:21:30.066918 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-17 00:21:30.068038 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-17 00:21:30.739200 | 
2025-09-17 00:21:30.739324 | PLAY [all]
2025-09-17 00:21:30.760046 | 
2025-09-17 00:21:30.760152 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-17 00:21:31.519899 | controller | changed: non-zero return code
2025-09-17 00:21:31.528160 | 
2025-09-17 00:21:31.528270 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-17 00:21:31.544454 | controller | skipping: Conditional result was False
2025-09-17 00:21:31.553794 | 
2025-09-17 00:21:31.553957 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-17 00:21:31.580947 | 
2025-09-17 00:21:31.581168 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-17 00:21:31.605557 | 
2025-09-17 00:21:31.605858 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-17 00:21:31.621518 | controller | skipping: Conditional result was False
2025-09-17 00:21:31.630314 | 
2025-09-17 00:21:31.630406 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-17 00:21:31.655608 | 
2025-09-17 00:21:31.655830 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-17 00:21:31.671096 | controller | skipping: Conditional result was False
2025-09-17 00:21:31.680192 | 
2025-09-17 00:21:31.680287 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-17 00:21:31.695573 | controller | skipping: Conditional result was False
2025-09-17 00:21:31.704208 | 
2025-09-17 00:21:31.704397 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-17 00:21:31.729698 | controller | skipping: Conditional result was False
2025-09-17 00:21:31.755406 | 
2025-09-17 00:21:31.755466 | PLAY RECAP
2025-09-17 00:21:31.755505 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-17 00:21:31.755525 | 
2025-09-17 00:21:31.860287 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-17 00:21:31.861140 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-17 00:21:32.479891 | 
2025-09-17 00:21:32.480035 | PLAY [all:!appliance*]
2025-09-17 00:21:32.505320 | 
2025-09-17 00:21:32.505465 | TASK [unregister the node]
2025-09-17 00:21:32.629522 | controller | skipping: Conditional result was False
2025-09-17 00:21:32.635630 | 
2025-09-17 00:21:32.635732 | TASK [include_role : fetch-output]
2025-09-17 00:21:32.670715 | controller | ok
2025-09-17 00:21:32.704128 | 
2025-09-17 00:21:32.704263 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-17 00:21:32.750077 | controller | skipping: Conditional result was False
2025-09-17 00:21:32.758797 | 
2025-09-17 00:21:32.758899 | TASK [fetch-output : Set log path for single node]
2025-09-17 00:21:32.791103 | controller | ok
2025-09-17 00:21:32.798795 | 
2025-09-17 00:21:32.798889 | LOOP [fetch-output : Ensure local output dirs]
2025-09-17 00:21:33.212097 | controller -> localhost | ok: "/var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/work/logs"
2025-09-17 00:21:33.478538 | controller -> localhost | changed: "/var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/work/artifacts"
2025-09-17 00:21:33.695442 | controller -> localhost | changed: "/var/lib/zuul/builds/fe78ee35bb4e497fb3d7f1eb05af6c9a/work/docs"
2025-09-17 00:21:33.710645 | 
2025-09-17 00:21:33.710864 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-17 00:21:34.949828 | controller | changed:
2025-09-17 00:21:34.950186 | controller | .d..t...... ./
2025-09-17 00:21:34.956173 | controller | cd+++++++++ controller/
2025-09-17 00:21:34.956267 | controller | changed: All items complete
2025-09-17 00:21:34.956316 | 
2025-09-17 00:21:35.969582 | controller | changed: .d..t...... ./
2025-09-17 00:21:37.018023 | controller | changed: .d..t...... ./
2025-09-17 00:21:37.059361 | 
2025-09-17 00:21:37.059576 | TASK [include_role : fetch-output-openshift]
2025-09-17 00:21:37.088831 | controller | skipping: Conditional result was False
2025-09-17 00:21:37.104490 | 
2025-09-17 00:21:37.104759 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-17 00:21:37.155873 | controller | skipping: Conditional result was False
2025-09-17 00:21:37.167198 | controller | skipping: Conditional result was False
2025-09-17 00:21:37.231106 | 
2025-09-17 00:21:37.231246 | PLAY [localhost]
2025-09-17 00:21:37.249057 | 
2025-09-17 00:21:37.249183 | TASK [Run Zuul manifest role]
2025-09-17 00:21:37.272876 | localhost | ok
2025-09-17 00:21:37.293391 | 
2025-09-17 00:21:37.293538 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-17 00:21:37.683045 | localhost | changed
2025-09-17 00:21:37.688572 | 
2025-09-17 00:21:37.688642 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-17 00:21:37.719194 | localhost | ok
2025-09-17 00:21:37.731584 | 
2025-09-17 00:21:37.731729 | TASK [Set zuul-log-path fact]
2025-09-17 00:21:37.754383 | localhost | ok
2025-09-17 00:21:37.774778 | 
2025-09-17 00:21:37.774887 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-17 00:21:37.806724 | localhost | ok
2025-09-17 00:21:37.819610 | 
2025-09-17 00:21:37.819716 | LOOP [Run upload-logs-swift role]
2025-09-17 00:21:37.855105 | localhost | Output suppressed because no_log was given
2025-09-17 00:21:37.892315 | 
2025-09-17 00:21:37.892570 | TASK [Set zuul-log-path fact]
2025-09-17 00:21:37.932027 | localhost | skipping: Conditional result was False
2025-09-17 00:21:37.937583 | 
2025-09-17 00:21:37.937685 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-17 00:21:38.451783 | localhost -> localhost | ok: Runtime: 0:00:00.008970
2025-09-17 00:21:38.460028 | 
2025-09-17 00:21:38.460121 | TASK [upload-logs-swift : Upload logs to swift]