2025-09-21 00:12:00.556016 | Job console starting...
2025-09-21 00:12:00.572273 | Updating repositories
2025-09-21 00:12:00.697695 | Preparing job workspace
2025-09-21 00:12:04.506327 | Running Ansible setup...
2025-09-21 00:12:10.876424 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-21 00:12:11.525564 | 
2025-09-21 00:12:11.525716 | PLAY [localhost]
2025-09-21 00:12:11.534150 | 
2025-09-21 00:12:11.534238 | TASK [Gathering Facts]
2025-09-21 00:12:12.608943 | localhost | ok
2025-09-21 00:12:12.638863 | 
2025-09-21 00:12:12.639024 | TASK [Setup log path fact]
2025-09-21 00:12:12.671854 | localhost | ok
2025-09-21 00:12:12.689218 | 
2025-09-21 00:12:12.689310 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-21 00:12:12.730617 | localhost | ok
2025-09-21 00:12:12.741366 | 
2025-09-21 00:12:12.741456 | TASK [emit-job-header : Print job information]
2025-09-21 00:12:12.772981 | # Job Information
2025-09-21 00:12:12.773134 | Ansible Version: 2.15.12
2025-09-21 00:12:12.773178 | Job: ansible-test-sanity-docker-milestone
2025-09-21 00:12:12.773207 | Pipeline: periodic
2025-09-21 00:12:12.773233 | Executor: ze02.softwarefactory-project.io
2025-09-21 00:12:12.773257 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-21 00:12:12.773286 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/4d0/ansible/4d0e636c88d74bee9a33710735dee0bb/
2025-09-21 00:12:12.773313 | Event ID: 27802346d2f84510bca22e156db61c7a
2025-09-21 00:12:12.778460 | 
2025-09-21 00:12:12.778546 | LOOP [emit-job-header : Print node information]
2025-09-21 00:12:12.906087 | localhost | ok:
2025-09-21 00:12:12.906497 | localhost | # Node Information
2025-09-21 00:12:12.906541 | localhost | Inventory Hostname: controller
2025-09-21 00:12:12.906569 | localhost | Hostname: ip-172-16-57-249
2025-09-21 00:12:12.906594 | localhost | Username: zuul-worker
2025-09-21 00:12:12.906619 | localhost | Distro: Fedora 37
2025-09-21 00:12:12.906641 | localhost | Provider: ansible-us-east-2
2025-09-21 00:12:12.906680 | localhost | Region: us-east-2
2025-09-21 00:12:12.906705 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-21 00:12:12.906723 | localhost | Product Name: t3.small
2025-09-21 00:12:12.906739 | localhost | Interface IP: 3.129.59.137
2025-09-21 00:12:12.927507 | 
2025-09-21 00:12:12.927683 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-21 00:12:13.440597 | localhost -> localhost | changed
2025-09-21 00:12:13.452947 | 
2025-09-21 00:12:13.453093 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-21 00:12:14.358977 | localhost -> localhost | changed
2025-09-21 00:12:14.378557 | 
2025-09-21 00:12:14.378615 | PLAY [all:!appliance*]
2025-09-21 00:12:14.393599 | 
2025-09-21 00:12:14.393677 | TASK [include_role : start-zuul-console]
2025-09-21 00:12:14.414240 | controller | ok
2025-09-21 00:12:14.427030 | 
2025-09-21 00:12:14.427091 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-21 00:12:15.002607 | controller | ok
2025-09-21 00:12:15.024959 | 
2025-09-21 00:12:15.025095 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-21 00:12:16.474118 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-21 00:12:16.487391 | 
2025-09-21 00:12:16.487539 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-21 00:12:16.633933 | controller | skipping: Conditional result was False
2025-09-21 00:12:16.647077 | 
2025-09-21 00:12:16.647214 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-21 00:12:16.674286 | controller | skipping: Conditional result was False
2025-09-21 00:12:16.688321 | 
2025-09-21 00:12:16.688457 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-21 00:12:16.714720 | controller | skipping: Conditional result was False
2025-09-21 00:12:16.727646 | 
2025-09-21 00:12:16.727809 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-21 00:12:16.754875 | controller | skipping: Conditional result was False
2025-09-21 00:12:16.767757 | 
2025-09-21 00:12:16.768172 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-21 00:12:16.794626 | controller | skipping: Conditional result was False
2025-09-21 00:12:16.809264 | 
2025-09-21 00:12:16.809453 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-21 00:12:16.836086 | controller | skipping: Conditional result was False
2025-09-21 00:12:16.863161 | 
2025-09-21 00:12:16.863306 | TASK [Disable Fedora Modular]
2025-09-21 00:12:17.585402 | controller | changed
2025-09-21 00:12:17.597123 | 
2025-09-21 00:12:17.597254 | TASK [Enable EPEL]
2025-09-21 00:12:17.623545 | controller | skipping: Conditional result was False
2025-09-21 00:12:17.636891 | 
2025-09-21 00:12:17.637071 | TASK [Register the RHEL node]
2025-09-21 00:12:17.805392 | 
2025-09-21 00:12:17.805711 | TASK [Show the subscription-manager status]
2025-09-21 00:12:17.967477 | controller | skipping: Conditional result was False
2025-09-21 00:12:18.018115 | 
2025-09-21 00:12:18.018262 | TASK [Enable EPEL on RHEL]
2025-09-21 00:12:18.159104 | controller | skipping: Conditional result was False
2025-09-21 00:12:18.171904 | 
2025-09-21 00:12:18.172038 | TASK [Install git and tox]
2025-09-21 00:13:48.504668 | controller | changed
2025-09-21 00:13:48.519946 | 
2025-09-21 00:13:48.520084 | TASK [include_role : prepare-workspace]
2025-09-21 00:13:48.560515 | controller | ok
2025-09-21 00:13:48.598390 | 
2025-09-21 00:13:48.598534 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-21 00:13:49.109297 | controller | ok
2025-09-21 00:13:49.123194 | 
2025-09-21 00:13:49.123330 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-21 00:14:02.160201 | controller | Output suppressed because no_log was given
2025-09-21 00:14:02.175437 | 
2025-09-21 00:14:02.175555 | TASK [include_role : prepare-workspace-openshift]
2025-09-21 00:14:02.201813 | controller | skipping: Conditional result was False
2025-09-21 00:14:02.228212 | 
2025-09-21 00:14:02.228295 | PLAY [all:!appliance]
2025-09-21 00:14:02.244602 | 
2025-09-21 00:14:02.244710 | TASK [Run add-build-sshkey role (RSA)]
2025-09-21 00:14:02.267785 | controller | ok
2025-09-21 00:14:02.284372 | 
2025-09-21 00:14:02.284447 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-21 00:14:02.525305 | controller -> localhost | ok
2025-09-21 00:14:02.583581 | 
2025-09-21 00:14:02.583810 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-21 00:14:02.619306 | controller | ok
2025-09-21 00:14:02.657191 | controller | included: /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-21 00:14:02.664548 | 
2025-09-21 00:14:02.664614 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-21 00:14:03.180024 | controller -> localhost | Generating public/private rsa key pair.
2025-09-21 00:14:03.180317 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/work/4d0e636c88d74bee9a33710735dee0bb_id_rsa.
2025-09-21 00:14:03.180348 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/work/4d0e636c88d74bee9a33710735dee0bb_id_rsa.pub.
2025-09-21 00:14:03.180370 | controller -> localhost | The key fingerprint is:
2025-09-21 00:14:03.180390 | controller -> localhost | SHA256:fO+loSlcwaD6nKx/sdYZF48Mv1Nyelh1ItipbhKk7iI zuul-build-sshkey
2025-09-21 00:14:03.180409 | controller -> localhost | The key's randomart image is:
2025-09-21 00:14:03.180427 | controller -> localhost | +---[RSA 2048]----+
2025-09-21 00:14:03.180445 | controller -> localhost | |                 |
2025-09-21 00:14:03.180464 | controller -> localhost | |        .        |
2025-09-21 00:14:03.180482 | controller -> localhost | |       . o o .   |
2025-09-21 00:14:03.180499 | controller -> localhost | |      ... = = . o|
2025-09-21 00:14:03.180516 | controller -> localhost | |     . oS .* = o.|
2025-09-21 00:14:03.180544 | controller -> localhost | |    . . o.+.* =  |
2025-09-21 00:14:03.180568 | controller -> localhost | |     = o B +oO.  |
2025-09-21 00:14:03.180589 | controller -> localhost | |  E . * B =+=+.  |
2025-09-21 00:14:03.180606 | controller -> localhost | |   ..=oo +o oo   |
2025-09-21 00:14:03.180626 | controller -> localhost | +----[SHA256]-----+
2025-09-21 00:14:03.180698 | controller -> localhost | ok: Runtime: 0:00:00.128454
2025-09-21 00:14:03.187743 | 
2025-09-21 00:14:03.187811 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-21 00:14:03.219102 | controller | ok
2025-09-21 00:14:03.229198 | controller | included: /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-21 00:14:03.238075 | 
2025-09-21 00:14:03.238147 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-21 00:14:03.262750 | controller | skipping: Conditional result was False
2025-09-21 00:14:03.270697 | 
2025-09-21 00:14:03.270783 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-21 00:14:04.116653 | controller | changed
2025-09-21 00:14:04.130530 | 
2025-09-21 00:14:04.130705 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-21 00:14:05.665849 | controller | ok
2025-09-21 00:14:05.678294 | 
2025-09-21 00:14:05.678437 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-21 00:14:07.078534 | controller | changed
2025-09-21 00:14:07.086296 | 
2025-09-21 00:14:07.086387 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-21 00:14:08.371219 | controller | changed
2025-09-21 00:14:08.378901 | 
2025-09-21 00:14:08.378978 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-21 00:14:08.413951 | controller | skipping: Conditional result was False
2025-09-21 00:14:08.421304 | 
2025-09-21 00:14:08.421376 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-21 00:14:08.786588 | controller -> localhost | changed
2025-09-21 00:14:08.811017 | 
2025-09-21 00:14:08.811163 | TASK [add-build-sshkey : Add back temp key]
2025-09-21 00:14:09.115874 | controller -> localhost | Identity added: /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/work/4d0e636c88d74bee9a33710735dee0bb_id_rsa (zuul-build-sshkey)
2025-09-21 00:14:09.116215 | controller -> localhost | ok: Runtime: 0:00:00.010518
2025-09-21 00:14:09.125811 | 
2025-09-21 00:14:09.125900 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-21 00:14:09.687844 | controller | ok
2025-09-21 00:14:09.701335 | 
2025-09-21 00:14:09.701472 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-21 00:14:09.741151 | controller | skipping: Conditional result was False
2025-09-21 00:14:09.765499 | 
2025-09-21 00:14:09.765594 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-21 00:14:09.800109 | controller | ok
2025-09-21 00:14:09.820926 | 
2025-09-21 00:14:09.821017 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-21 00:14:10.090903 | controller -> localhost | ok
2025-09-21 00:14:10.098568 | 
2025-09-21 00:14:10.098641 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-21 00:14:10.129605 | controller | ok
2025-09-21 00:14:10.140240 | controller | included: /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-21 00:14:10.146239 | 
2025-09-21 00:14:10.146297 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-21 00:14:10.415793 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-21 00:14:10.416055 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/work/4d0e636c88d74bee9a33710735dee0bb_id_ecdsa.
2025-09-21 00:14:10.416084 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/work/4d0e636c88d74bee9a33710735dee0bb_id_ecdsa.pub.
2025-09-21 00:14:10.416114 | controller -> localhost | The key fingerprint is:
2025-09-21 00:14:10.416134 | controller -> localhost | SHA256:ONIoGTSHyo669/4OzQ1c745vonv+hq7xWuwiv42cvlA zuul-build-sshkey
2025-09-21 00:14:10.416154 | controller -> localhost | The key's randomart image is:
2025-09-21 00:14:10.416200 | controller -> localhost | +---[ECDSA 521]---+
2025-09-21 00:14:10.416221 | controller -> localhost | |  o..            |
2025-09-21 00:14:10.416238 | controller -> localhost | | ..o             |
2025-09-21 00:14:10.416255 | controller -> localhost | |...     .        |
2025-09-21 00:14:10.416272 | controller -> localhost | |.. o + o .       |
2025-09-21 00:14:10.416289 | controller -> localhost | |o o o E S .      |
2025-09-21 00:14:10.416305 | controller -> localhost | |.. . = = .       |
2025-09-21 00:14:10.416321 | controller -> localhost | |.   o + +..      |
2025-09-21 00:14:10.416338 | controller -> localhost | |. . .+.O+oo      |
2025-09-21 00:14:10.416354 | controller -> localhost | |.o oo*/%B*+      |
2025-09-21 00:14:10.416370 | controller -> localhost | +----[SHA256]-----+
2025-09-21 00:14:10.416417 | controller -> localhost | ok: Runtime: 0:00:00.016607
2025-09-21 00:14:10.423373 | 
2025-09-21 00:14:10.423439 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-21 00:14:10.454604 | controller | ok
2025-09-21 00:14:10.465037 | controller | included: /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-21 00:14:10.473724 | 
2025-09-21 00:14:10.473785 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-21 00:14:10.497914 | controller | skipping: Conditional result was False
2025-09-21 00:14:10.504063 | 
2025-09-21 00:14:10.504130 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-21 00:14:10.972126 | controller | changed
2025-09-21 00:14:10.979721 | 
2025-09-21 00:14:10.979892 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-21 00:14:11.348586 | controller | ok
2025-09-21 00:14:11.363969 | 
2025-09-21 00:14:11.364188 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-21 00:14:12.648041 | controller | changed
2025-09-21 00:14:12.660423 | 
2025-09-21 00:14:12.660568 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-21 00:14:13.941206 | controller | changed
2025-09-21 00:14:13.953860 | 
2025-09-21 00:14:13.954001 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-21 00:14:13.991962 | controller | skipping: Conditional result was False
2025-09-21 00:14:14.005596 | 
2025-09-21 00:14:14.005803 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-21 00:14:14.287941 | controller -> localhost | changed
2025-09-21 00:14:14.298959 | 
2025-09-21 00:14:14.299026 | TASK [add-build-sshkey : Add back temp key]
2025-09-21 00:14:14.567937 | controller -> localhost | Identity added: /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/work/4d0e636c88d74bee9a33710735dee0bb_id_ecdsa (zuul-build-sshkey)
2025-09-21 00:14:14.568271 | controller -> localhost | ok: Runtime: 0:00:00.011661
2025-09-21 00:14:14.578656 | 
2025-09-21 00:14:14.578813 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-21 00:14:14.886922 | controller | ok
2025-09-21 00:14:14.892512 | 
2025-09-21 00:14:14.892579 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-21 00:14:14.920134 | controller | skipping: Conditional result was False
2025-09-21 00:14:14.930826 | 
2025-09-21 00:14:14.930891 | TASK [include_role : remove-zuul-sshkey]
2025-09-21 00:14:14.954911 | controller | skipping: Conditional result was False
2025-09-21 00:14:14.967212 | 
2025-09-21 00:14:14.967317 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-21 00:14:15.280560 | controller | ok: "logs"
2025-09-21 00:14:15.280975 | controller | ok: All items complete
2025-09-21 00:14:15.281017 | 
2025-09-21 00:14:15.558593 | controller | ok: "artifacts"
2025-09-21 00:14:15.843276 | controller | ok: "docs"
2025-09-21 00:14:15.859621 | 
2025-09-21 00:14:15.859781 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-21 00:14:16.195370 | controller | changed: "logs"
2025-09-21 00:14:16.517478 | controller | changed: "artifacts"
2025-09-21 00:14:16.806389 | controller | changed: "docs"
2025-09-21 00:14:16.874007 | 
2025-09-21 00:14:16.874199 | PLAY RECAP
2025-09-21 00:14:16.874295 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-21 00:14:16.874350 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-21 00:14:16.874388 | 
2025-09-21 00:14:17.073121 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-21 00:14:17.073980 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-21 00:14:17.633417 | 
2025-09-21 00:14:17.633561 | PLAY [all]
2025-09-21 00:14:17.655016 | 
2025-09-21 00:14:17.655107 | TASK [Install binary dependencies]
2025-09-21 00:14:17.716101 | controller | ok
2025-09-21 00:14:17.735982 | 
2025-09-21 00:14:17.736094 | TASK [bindep : Include find tasks]
2025-09-21 00:14:17.777610 | controller | ok
2025-09-21 00:14:17.788073 | controller | included: /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-21 00:14:17.796006 | 
2025-09-21 00:14:17.796091 | TASK [bindep : Look for bindep.txt]
2025-09-21 00:14:18.301035 | controller | ok
2025-09-21 00:14:18.314528 | 
2025-09-21 00:14:18.314975 | TASK [bindep : Define bindep_file fact]
2025-09-21 00:14:18.343154 | controller | skipping: Conditional result was False
2025-09-21 00:14:18.352812 | 
2025-09-21 00:14:18.352933 | TASK [bindep : Look for other-requirements.txt]
2025-09-21 00:14:18.653368 | controller | ok
2025-09-21 00:14:18.665180 | 
2025-09-21 00:14:18.665331 | TASK [bindep : Define bindep_file fact]
2025-09-21 00:14:18.692046 | controller | skipping: Conditional result was False
2025-09-21 00:14:18.704441 | 
2025-09-21 00:14:18.704539 | TASK [bindep : Look for bindep fallback file]
2025-09-21 00:14:18.729931 | controller | skipping: Conditional result was False
2025-09-21 00:14:18.742351 | 
2025-09-21 00:14:18.742496 | TASK [bindep : Define bindep_file fact]
2025-09-21 00:14:18.769283 | controller | skipping: Conditional result was False
2025-09-21 00:14:18.789919 | 
2025-09-21 00:14:18.790101 | TASK [bindep : Include bindep tasks]
2025-09-21 00:14:18.827763 | controller | skipping: Conditional result was False
2025-09-21 00:14:18.838316 | 
2025-09-21 00:14:18.838410 | TASK [bindep : Include install tasks]
2025-09-21 00:14:18.874866 | controller | skipping: Conditional result was False
2025-09-21 00:14:18.884093 | 
2025-09-21 00:14:18.884202 | LOOP [bindep : Include package tasks]
2025-09-21 00:14:18.966014 | 
2025-09-21 00:14:18.966236 | TASK [Run test-setup role]
2025-09-21 00:14:18.988768 | controller | ok
2025-09-21 00:14:19.007098 | 
2025-09-21 00:14:19.007171 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-21 00:14:19.309786 | controller | ok
2025-09-21 00:14:19.315638 | 
2025-09-21 00:14:19.315720 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-21 00:14:19.450795 | controller | skipping: Conditional result was False
2025-09-21 00:14:19.475801 | 
2025-09-21 00:14:19.475864 | PLAY RECAP
2025-09-21 00:14:19.475904 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-21 00:14:19.475924 | 
2025-09-21 00:14:19.629357 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-21 00:14:19.631060 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-21 00:14:20.238393 | 
2025-09-21 00:14:20.238529 | PLAY [controller]
2025-09-21 00:14:20.258282 | 
2025-09-21 00:14:20.258382 | TASK [Create the /root directory]
2025-09-21 00:14:20.973314 | controller | ok
2025-09-21 00:14:20.979062 | 
2025-09-21 00:14:20.979134 | TASK [Install glibc-langpack-en]
2025-09-21 00:14:29.265873 | controller | ok: Nothing to do
2025-09-21 00:14:29.277052 | 
2025-09-21 00:14:29.277169 | TASK [Ensure controller directory exists]
2025-09-21 00:14:29.698401 | controller | changed
2025-09-21 00:14:29.707076 | 
2025-09-21 00:14:29.707220 | TASK [Install container runtime]
2025-09-21 00:14:29.762087 | controller | ok
2025-09-21 00:14:29.814305 | 
2025-09-21 00:14:29.814448 | LOOP [ensure-podman : Find distribution installation]
2025-09-21 00:14:29.860798 | controller | ok: "/var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-21 00:14:29.878740 | controller | included: /var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-21 00:14:29.889039 | 
2025-09-21 00:14:29.889128 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-21 00:15:46.237598 | controller | changed
2025-09-21 00:15:46.245947 | 
2025-09-21 00:15:46.246037 | TASK [ensure-podman : Fetch podman version]
2025-09-21 00:15:47.033258 | controller | Client:       Podman Engine
2025-09-21 00:15:47.033348 | controller | Version:      4.6.2
2025-09-21 00:15:47.033387 | controller | API Version:  4.6.2
2025-09-21 00:15:47.033427 | controller | Go Version:   go1.19.12
2025-09-21 00:15:47.033483 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-21 00:15:47.033525 | controller | OS/Arch:      linux/amd64
2025-09-21 00:15:47.389433 | controller | ok: Runtime: 0:00:00.245702
2025-09-21 00:15:47.402493 | 
2025-09-21 00:15:47.402624 | TASK [ensure-podman : Print podman version installed]
2025-09-21 00:15:47.439916 | Podman version: Client:       Podman Engine
2025-09-21 00:15:47.440139 | Version:      4.6.2
2025-09-21 00:15:47.440181 | API Version:  4.6.2
2025-09-21 00:15:47.440212 | Go Version:   go1.19.12
2025-09-21 00:15:47.440240 | Built:        Mon Aug 28 19:38:31 2023
2025-09-21 00:15:47.440268 | OS/Arch:      linux/amd64
2025-09-21 00:15:47.457708 | 
2025-09-21 00:15:47.457823 | TASK [ensure-podman : Validate podman engine]
2025-09-21 00:15:47.591331 | controller | skipping: Conditional result was False
2025-09-21 00:15:47.604425 | 
2025-09-21 00:15:47.604567 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-21 00:15:47.652846 | controller | skipping: Conditional result was False
2025-09-21 00:15:47.689900 | 
2025-09-21 00:15:47.689998 | TASK [Ensure python3.8 is present]
2025-09-21 00:15:47.725693 | controller | skipping: Conditional result was False
2025-09-21 00:15:47.733349 | 
2025-09-21 00:15:47.733436 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-21 00:15:47.755865 | controller | ok
2025-09-21 00:15:47.779245 | 
2025-09-21 00:15:47.779313 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-21 00:15:51.738042 | controller | ok: Nothing to do
2025-09-21 00:15:51.751022 | 
2025-09-21 00:15:51.751363 | TASK [our-ensure-python : Also install python3-devel]
2025-09-21 00:16:05.810712 | controller | changed
2025-09-21 00:16:05.834421 | 
2025-09-21 00:16:05.834571 | TASK [Run ensure-virtualenv role]
2025-09-21 00:16:05.865347 | controller | ok
2025-09-21 00:16:05.899530 | 
2025-09-21 00:16:05.899717 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-21 00:16:06.285137 | controller | /usr/bin/virtualenv
2025-09-21 00:16:06.532658 | controller | ok: Runtime: 0:00:00.004805
2025-09-21 00:16:06.545938 | 
2025-09-21 00:16:06.546081 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-21 00:16:06.584199 | controller | skipping: Conditional result was False
2025-09-21 00:16:06.584835 | controller | ok: All items complete
2025-09-21 00:16:06.584908 | 
2025-09-21 00:16:06.656242 | 
2025-09-21 00:16:06.656440 | TASK [Find the full path of the Python interpreter]
2025-09-21 00:16:07.087083 | controller | /usr/bin/python3
2025-09-21 00:16:07.281174 | controller | ok
2025-09-21 00:16:07.293009 | 
2025-09-21 00:16:07.293150 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-21 00:16:08.856189 | controller | created virtual environment CPython3.11.0.final.0-64 in 776ms
2025-09-21 00:16:08.903373 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-21 00:16:08.903440 | 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-21 00:16:08.903461 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-21 00:16:08.903486 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-21 00:16:08.972186 | controller | changed
2025-09-21 00:16:08.983792 | 
2025-09-21 00:16:08.983926 | TASK [Set selinux package]
2025-09-21 00:16:09.012065 | controller | ok
2025-09-21 00:16:09.022733 | 
2025-09-21 00:16:09.022877 | TASK [Set selinux package (Fedora)]
2025-09-21 00:16:09.080772 | controller | ok
2025-09-21 00:16:09.091238 | 
2025-09-21 00:16:09.091375 | TASK [Install selinux into virtualenv]
2025-09-21 00:16:11.762562 | controller | Collecting selinux-please-lie-to-me
2025-09-21 00:16:11.853670 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-21 00:16:12.392647 | controller | Collecting setuptools<50.0.0
2025-09-21 00:16:12.405681 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-21 00:16:12.531758 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00
2025-09-21 00:16:12.689014 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-21 00:16:12.689441 | controller |   Attempting uninstall: setuptools
2025-09-21 00:16:12.694508 | controller |     Found existing installation: setuptools 62.6.0
2025-09-21 00:16:12.807643 | controller |     Uninstalling setuptools-62.6.0:
2025-09-21 00:16:12.823203 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-21 00:16:13.604863 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-21 00:16:13.822367 | controller |
2025-09-21 00:16:14.043402 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-21 00:16:14.043464 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-21 00:16:14.262130 | controller | ok: Runtime: 0:00:04.471459
2025-09-21 00:16:14.273967 | 
2025-09-21 00:16:14.274101 | TASK [Install pytest-forked into virtualenv]
2025-09-21 00:16:15.495739 | controller | Collecting pytest-forked
2025-09-21 00:16:15.582960 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-21 00:16:15.643612 | controller | Collecting py
2025-09-21 00:16:15.656851 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-21 00:16:15.693611 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-09-21 00:16:15.865669 | controller | Collecting pytest>=3.10
2025-09-21 00:16:15.881312 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-21 00:16:15.939558 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.6 MB/s eta 0:00:00
2025-09-21 00:16:15.994788 | controller | Collecting iniconfig>=1
2025-09-21 00:16:16.007046 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-21 00:16:16.070978 | controller | Collecting packaging>=20
2025-09-21 00:16:16.083930 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-21 00:16:16.096304 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.4 MB/s eta 0:00:00
2025-09-21 00:16:16.144182 | controller | Collecting pluggy<2,>=1.5
2025-09-21 00:16:16.156399 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-21 00:16:16.228251 | controller | Collecting pygments>=2.7.2
2025-09-21 00:16:16.240282 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-21 00:16:16.356019 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.9 MB/s eta 0:00:00
2025-09-21 00:16:16.491025 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-21 00:16:18.744242 | 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-21 00:16:18.760393 | controller |
2025-09-21 00:16:18.951749 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-21 00:16:18.951794 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-21 00:16:19.431783 | controller | ok: Runtime: 0:00:04.193300
2025-09-21 00:16:19.446473 | 
2025-09-21 00:16:19.446620 | TASK [Update pip]
2025-09-21 00:16:20.624680 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-21 00:16:20.902938 | controller | Collecting pip
2025-09-21 00:16:21.000842 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-21 00:16:21.189143 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.5 MB/s eta 0:00:00
2025-09-21 00:16:21.342473 | controller | Installing collected packages: pip
2025-09-21 00:16:21.342770 | controller |   Attempting uninstall: pip
2025-09-21 00:16:21.347479 | controller |     Found existing installation: pip 22.2.2
2025-09-21 00:16:21.607122 | controller |     Uninstalling pip-22.2.2:
2025-09-21 00:16:21.638715 | controller |       Successfully uninstalled pip-22.2.2
2025-09-21 00:16:23.444865 | controller | Successfully installed pip-25.2
2025-09-21 00:16:24.123930 | controller | ok: Runtime: 0:00:03.622856
2025-09-21 00:16:24.137409 | 
2025-09-21 00:16:24.137556 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-21 00:16:24.687913 | controller | changed
2025-09-21 00:16:24.701742 | 
2025-09-21 00:16:24.701911 | TASK [Install ansible into virtualenv]
2025-09-21 00:16:25.776482 | controller | Processing ./src/github.com/ansible/ansible
2025-09-21 00:16:25.783217 | controller |   Installing build dependencies: started
2025-09-21 00:16:27.802737 | controller |   Installing build dependencies: finished with status 'done'
2025-09-21 00:16:29.339971 | controller |   Getting requirements to build wheel: started
2025-09-21 00:16:29.340038 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-21 00:16:30.261975 | controller |   Preparing metadata (pyproject.toml): started
2025-09-21 00:16:30.262029 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-21 00:16:30.264631 | 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-21 00:16:30.269577 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-21 00:16:30.867953 | controller | ERROR
2025-09-21 00:16:30.868395 | controller | {
2025-09-21 00:16:30.868464 | controller |   "delta": "0:00:05.281915",
2025-09-21 00:16:30.868508 | controller |   "end": "2025-09-21 00:16:30.422931",
2025-09-21 00:16:30.868546 | controller |   "msg": "non-zero return code",
2025-09-21 00:16:30.868599 | controller |   "rc": 1,
2025-09-21 00:16:30.868636 | controller |   "start": "2025-09-21 00:16:25.141016"
2025-09-21 00:16:30.868710 | controller | }
failure
2025-09-21 00:16:30.871298 | 
2025-09-21 00:16:30.871394 | PLAY RECAP
2025-09-21 00:16:30.871479 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-21 00:16:30.871525 | 
2025-09-21 00:16:31.016922 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-21 00:16:31.018948 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-21 00:16:31.597074 | 
2025-09-21 00:16:31.597195 | PLAY [all]
2025-09-21 00:16:31.618118 | 
2025-09-21 00:16:31.618214 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-21 00:16:32.412272 | controller | changed: non-zero return code
2025-09-21 00:16:32.426780 | 
2025-09-21 00:16:32.427023 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-21 00:16:32.453600 | controller | skipping: Conditional result was False
2025-09-21 00:16:32.468597 | 
2025-09-21 00:16:32.468758 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-21 00:16:32.523209 | 
2025-09-21 00:16:32.523413 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-21 00:16:32.557786 | 
2025-09-21 00:16:32.557999 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-21 00:16:32.577332 | controller | skipping: Conditional result was False
2025-09-21 00:16:32.583613 | 
2025-09-21 00:16:32.583707 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-21 00:16:32.605162 | 
2025-09-21 00:16:32.605304 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-21 00:16:32.619371 | controller | skipping: Conditional result was False
2025-09-21 00:16:32.626215 | 
2025-09-21 00:16:32.626296 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-21 00:16:32.640359 | controller | skipping: Conditional result was False
2025-09-21 00:16:32.647850 | 
2025-09-21 00:16:32.647931 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-21 00:16:32.662126 | controller | skipping: Conditional result was False
2025-09-21 00:16:32.689724 | 
2025-09-21 00:16:32.689785 | PLAY RECAP
2025-09-21 00:16:32.689832 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-21 00:16:32.689851 | 
2025-09-21 00:16:32.807115 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-21 00:16:32.808940 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-21 00:16:33.509399 | 
2025-09-21 00:16:33.509568 | PLAY [all:!appliance*]
2025-09-21 00:16:33.531238 | 
2025-09-21 00:16:33.531352 | TASK [unregister the node]
2025-09-21 00:16:33.654777 | controller | skipping: Conditional result was False
2025-09-21 00:16:33.668072 | 
2025-09-21 00:16:33.668250 | TASK [include_role : fetch-output]
2025-09-21 00:16:33.717424 | controller | ok
2025-09-21 00:16:33.753497 | 
2025-09-21 00:16:33.753643 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-21 00:16:33.830405 | controller | skipping: Conditional result was False
2025-09-21 00:16:33.842905 | 
2025-09-21 00:16:33.843091 | TASK [fetch-output : Set log path for single node]
2025-09-21 00:16:33.902196 | controller | ok
2025-09-21 00:16:33.913580 | 
2025-09-21 00:16:33.913750 | LOOP [fetch-output : Ensure local output dirs]
2025-09-21 00:16:34.384840 | controller -> localhost | ok: "/var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/work/logs"
2025-09-21 00:16:34.665570 | controller -> localhost | changed: "/var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/work/artifacts"
2025-09-21 00:16:34.887386 | controller -> localhost | changed: "/var/lib/zuul/builds/4d0e636c88d74bee9a33710735dee0bb/work/docs"
2025-09-21 00:16:34.904136 | 
2025-09-21 00:16:34.904340 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-21 00:16:36.202254 | controller | changed:
2025-09-21 00:16:36.202488 | controller | .d..t...... ./
2025-09-21 00:16:36.202515 | controller | cd+++++++++ controller/
2025-09-21 00:16:36.202548 | controller | changed: All items complete
2025-09-21 00:16:36.202568 | 
2025-09-21 00:16:37.202242 | controller | changed: .d..t...... ./
2025-09-21 00:16:38.259410 | controller | changed: .d..t...... ./
2025-09-21 00:16:38.290182 | 
2025-09-21 00:16:38.290319 | TASK [include_role : fetch-output-openshift]
2025-09-21 00:16:38.315554 | controller | skipping: Conditional result was False
2025-09-21 00:16:38.326453 | 
2025-09-21 00:16:38.326604 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-21 00:16:38.379443 | controller | skipping: Conditional result was False
2025-09-21 00:16:38.393756 | controller | skipping: Conditional result was False
2025-09-21 00:16:38.437842 | 
2025-09-21 00:16:38.437982 | PLAY [localhost]
2025-09-21 00:16:38.455702 | 
2025-09-21 00:16:38.455790 | TASK [Run Zuul manifest role]
2025-09-21 00:16:38.476951 | localhost | ok
2025-09-21 00:16:38.491557 | 
2025-09-21 00:16:38.491677 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-21 00:16:38.885468 | localhost | changed
2025-09-21 00:16:38.896543 | 
2025-09-21 00:16:38.896702 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-21 00:16:38.933248 | localhost | ok
2025-09-21 00:16:38.952189 | 
2025-09-21 00:16:38.952338 | TASK [Set zuul-log-path fact]
2025-09-21 00:16:38.973821 | localhost | ok
2025-09-21 00:16:38.994391 | 
2025-09-21 00:16:38.994488 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-21 00:16:39.026164 | localhost | ok
2025-09-21 00:16:39.039705 | 
2025-09-21 00:16:39.039793 | LOOP [Run upload-logs-swift role]
2025-09-21 00:16:39.064877 | localhost | Output suppressed because no_log was given
2025-09-21 00:16:39.103800 | 
2025-09-21 00:16:39.103881 | TASK [Set zuul-log-path fact]
2025-09-21 00:16:39.127969 | localhost | skipping: Conditional result was False
2025-09-21 00:16:39.133019 | 
2025-09-21 00:16:39.133082 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-21 00:16:39.534592 | localhost -> localhost | ok: Runtime: 0:00:00.010363
2025-09-21 00:16:39.553776 | 
2025-09-21 00:16:39.553941 | TASK [upload-logs-swift : Upload logs to swift]