2025-10-12 00:21:08.530437 | Job console starting...
2025-10-12 00:21:08.542575 | Updating repositories
2025-10-12 00:21:08.661885 | Preparing job workspace
2025-10-12 00:21:12.456181 | Running Ansible setup...
2025-10-12 00:21:18.598722 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-12 00:21:19.189354 | 
2025-10-12 00:21:19.189467 | PLAY [localhost]
2025-10-12 00:21:19.197798 | 
2025-10-12 00:21:19.197867 | TASK [Gathering Facts]
2025-10-12 00:21:20.217221 | localhost | ok
2025-10-12 00:21:20.255903 | 
2025-10-12 00:21:20.256099 | TASK [Setup log path fact]
2025-10-12 00:21:20.276544 | localhost | ok
2025-10-12 00:21:20.292978 | 
2025-10-12 00:21:20.293066 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-12 00:21:20.332865 | localhost | ok
2025-10-12 00:21:20.343079 | 
2025-10-12 00:21:20.343168 | TASK [emit-job-header : Print job information]
2025-10-12 00:21:20.396865 | # Job Information
2025-10-12 00:21:20.397077 | Ansible Version: 2.15.12
2025-10-12 00:21:20.397145 | Job: ansible-test-sanity-docker-devel
2025-10-12 00:21:20.397218 | Pipeline: periodic
2025-10-12 00:21:20.397261 | Executor: ze02.softwarefactory-project.io
2025-10-12 00:21:20.397301 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-12 00:21:20.397346 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/33a/ansible/33afdf37fe2045ec850525d6fafdfded/
2025-10-12 00:21:20.397387 | Event ID: 6345c3b581e843d6946dd6bca9ffe8f8
2025-10-12 00:21:20.405244 | 
2025-10-12 00:21:20.405383 | LOOP [emit-job-header : Print node information]
2025-10-12 00:21:20.528220 | localhost | ok:
2025-10-12 00:21:20.528477 | localhost | # Node Information
2025-10-12 00:21:20.528535 | localhost | Inventory Hostname: controller
2025-10-12 00:21:20.528578 | localhost | Hostname: ip-172-16-155-212
2025-10-12 00:21:20.528621 | localhost | Username: zuul-worker
2025-10-12 00:21:20.528672 | localhost | Distro: Fedora 37
2025-10-12 00:21:20.528764 | localhost | Provider: ansible-us-east-2
2025-10-12 00:21:20.528809 | localhost | Region: us-east-2
2025-10-12 00:21:20.528849 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-12 00:21:20.528887 | localhost | Product Name: t3.small
2025-10-12 00:21:20.528926 | localhost | Interface IP: 13.59.34.199
2025-10-12 00:21:20.545412 | 
2025-10-12 00:21:20.545546 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-12 00:21:20.940383 | localhost -> localhost | changed
2025-10-12 00:21:20.945904 | 
2025-10-12 00:21:20.945969 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-12 00:21:21.836820 | localhost -> localhost | changed
2025-10-12 00:21:21.856289 | 
2025-10-12 00:21:21.856342 | PLAY [all:!appliance*]
2025-10-12 00:21:21.871160 | 
2025-10-12 00:21:21.871220 | TASK [include_role : start-zuul-console]
2025-10-12 00:21:21.890863 | controller | ok
2025-10-12 00:21:21.903700 | 
2025-10-12 00:21:21.903761 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-12 00:21:22.587533 | controller | ok
2025-10-12 00:21:22.609795 | 
2025-10-12 00:21:22.609930 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-12 00:21:24.314913 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-12 00:21:24.323187 | 
2025-10-12 00:21:24.323269 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-12 00:21:24.461656 | controller | skipping: Conditional result was False
2025-10-12 00:21:24.474105 | 
2025-10-12 00:21:24.474243 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-12 00:21:24.501014 | controller | skipping: Conditional result was False
2025-10-12 00:21:24.513010 | 
2025-10-12 00:21:24.513144 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-12 00:21:24.539655 | controller | skipping: Conditional result was False
2025-10-12 00:21:24.552134 | 
2025-10-12 00:21:24.552272 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-12 00:21:24.578923 | controller | skipping: Conditional result was False
2025-10-12 00:21:24.590895 | 
2025-10-12 00:21:24.591039 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-12 00:21:24.617426 | controller | skipping: Conditional result was False
2025-10-12 00:21:24.629702 | 
2025-10-12 00:21:24.629840 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-12 00:21:24.655999 | controller | skipping: Conditional result was False
2025-10-12 00:21:24.680494 | 
2025-10-12 00:21:24.680623 | TASK [Disable Fedora Modular]
2025-10-12 00:21:25.426217 | controller | changed
2025-10-12 00:21:25.438265 | 
2025-10-12 00:21:25.438401 | TASK [Enable EPEL]
2025-10-12 00:21:25.466576 | controller | skipping: Conditional result was False
2025-10-12 00:21:25.478983 | 
2025-10-12 00:21:25.479122 | TASK [Register the RHEL node]
2025-10-12 00:21:25.649640 | 
2025-10-12 00:21:25.649945 | TASK [Show the subscription-manager status]
2025-10-12 00:21:25.818403 | controller | skipping: Conditional result was False
2025-10-12 00:21:25.855452 | 
2025-10-12 00:21:25.855579 | TASK [Enable EPEL on RHEL]
2025-10-12 00:21:26.014299 | controller | skipping: Conditional result was False
2025-10-12 00:21:26.026953 | 
2025-10-12 00:21:26.027091 | TASK [Install git and tox]
2025-10-12 00:22:56.565993 | controller | changed
2025-10-12 00:22:56.581153 | 
2025-10-12 00:22:56.581242 | TASK [include_role : prepare-workspace]
2025-10-12 00:22:56.614122 | controller | ok
2025-10-12 00:22:56.645890 | 
2025-10-12 00:22:56.645981 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-12 00:22:57.245633 | controller | ok
2025-10-12 00:22:57.258247 | 
2025-10-12 00:22:57.258526 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-12 00:23:10.472007 | controller | Output suppressed because no_log was given
2025-10-12 00:23:10.481593 | 
2025-10-12 00:23:10.481652 | TASK [include_role : prepare-workspace-openshift]
2025-10-12 00:23:10.505636 | controller | skipping: Conditional result was False
2025-10-12 00:23:10.526087 | 
2025-10-12 00:23:10.526139 | PLAY [all:!appliance]
2025-10-12 00:23:10.540548 | 
2025-10-12 00:23:10.540605 | TASK [Run add-build-sshkey role (RSA)]
2025-10-12 00:23:10.569256 | controller | ok
2025-10-12 00:23:10.608270 | 
2025-10-12 00:23:10.608388 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-12 00:23:10.835484 | controller -> localhost | ok
2025-10-12 00:23:10.841649 | 
2025-10-12 00:23:10.841743 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-12 00:23:10.871120 | controller | ok
2025-10-12 00:23:10.884224 | controller | included: /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-12 00:23:10.890169 | 
2025-10-12 00:23:10.890227 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-12 00:23:11.331573 | controller -> localhost | Generating public/private rsa key pair.
2025-10-12 00:23:11.331815 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/work/33afdf37fe2045ec850525d6fafdfded_id_rsa.
2025-10-12 00:23:11.331847 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/work/33afdf37fe2045ec850525d6fafdfded_id_rsa.pub.
2025-10-12 00:23:11.331869 | controller -> localhost | The key fingerprint is:
2025-10-12 00:23:11.331889 | controller -> localhost | SHA256:oHhmE+CuwRT1Bmzw9rD6trc/T0vIW/HxJEKgDaW9Z3E zuul-build-sshkey
2025-10-12 00:23:11.331909 | controller -> localhost | The key's randomart image is:
2025-10-12 00:23:11.331928 | controller -> localhost | +---[RSA 2048]----+
2025-10-12 00:23:11.331946 | controller -> localhost | | o=o ..o         |
2025-10-12 00:23:11.331965 | controller -> localhost | | .o+o * .        |
2025-10-12 00:23:11.331983 | controller -> localhost | | .o+.=.o o E     |
2025-10-12 00:23:11.332001 | controller -> localhost | |o...=o .o o      |
2025-10-12 00:23:11.332019 | controller -> localhost | |..o.*. .S= o .   |
2025-10-12 00:23:11.332047 | controller -> localhost | | o.+ .. + + =    |
2025-10-12 00:23:11.332070 | controller -> localhost | |..     o + . .   |
2025-10-12 00:23:11.332093 | controller -> localhost | |  .. . .= .      |
2025-10-12 00:23:11.332112 | controller -> localhost | |  .oo.oooo       |
2025-10-12 00:23:11.332132 | controller -> localhost | +----[SHA256]-----+
2025-10-12 00:23:11.332178 | controller -> localhost | ok: Runtime: 0:00:00.103171
2025-10-12 00:23:11.338131 | 
2025-10-12 00:23:11.338190 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-12 00:23:11.358560 | controller | ok
2025-10-12 00:23:11.370944 | controller | included: /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-12 00:23:11.379683 | 
2025-10-12 00:23:11.379751 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-12 00:23:11.392968 | controller | skipping: Conditional result was False
2025-10-12 00:23:11.400021 | 
2025-10-12 00:23:11.400092 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-12 00:23:11.997436 | controller | changed
2025-10-12 00:23:12.009659 | 
2025-10-12 00:23:12.009850 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-12 00:23:12.348251 | controller | ok
2025-10-12 00:23:12.362464 | 
2025-10-12 00:23:12.362560 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-12 00:23:13.699526 | controller | changed
2025-10-12 00:23:13.711703 | 
2025-10-12 00:23:13.711835 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-12 00:23:15.000556 | controller | changed
2025-10-12 00:23:15.013842 | 
2025-10-12 00:23:15.013974 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-12 00:23:15.042483 | controller | skipping: Conditional result was False
2025-10-12 00:23:15.056859 | 
2025-10-12 00:23:15.057001 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-12 00:23:15.490942 | controller -> localhost | changed
2025-10-12 00:23:15.506906 | 
2025-10-12 00:23:15.506979 | TASK [add-build-sshkey : Add back temp key]
2025-10-12 00:23:15.763525 | controller -> localhost | Identity added: /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/work/33afdf37fe2045ec850525d6fafdfded_id_rsa (zuul-build-sshkey)
2025-10-12 00:23:15.763749 | controller -> localhost | ok: Runtime: 0:00:00.007784
2025-10-12 00:23:15.769838 | 
2025-10-12 00:23:15.769897 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-12 00:23:16.276524 | controller | ok
2025-10-12 00:23:16.281810 | 
2025-10-12 00:23:16.281873 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-12 00:23:16.315964 | controller | skipping: Conditional result was False
2025-10-12 00:23:16.327225 | 
2025-10-12 00:23:16.327285 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-12 00:23:16.356092 | controller | ok
2025-10-12 00:23:16.371535 | 
2025-10-12 00:23:16.371700 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-12 00:23:16.608482 | controller -> localhost | ok
2025-10-12 00:23:16.614826 | 
2025-10-12 00:23:16.614891 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-12 00:23:16.645378 | controller | ok
2025-10-12 00:23:16.656106 | controller | included: /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-12 00:23:16.661512 | 
2025-10-12 00:23:16.661574 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-12 00:23:16.981972 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-12 00:23:16.982268 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/work/33afdf37fe2045ec850525d6fafdfded_id_ecdsa.
2025-10-12 00:23:16.982331 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/work/33afdf37fe2045ec850525d6fafdfded_id_ecdsa.pub.
2025-10-12 00:23:16.982394 | controller -> localhost | The key fingerprint is:
2025-10-12 00:23:16.982441 | controller -> localhost | SHA256:DiB3wlgYAm+IdKiwl5ZqCndk3GQLwM8Mqq+M4iTLfTY zuul-build-sshkey
2025-10-12 00:23:16.982485 | controller -> localhost | The key's randomart image is:
2025-10-12 00:23:16.982528 | controller -> localhost | +---[ECDSA 521]---+
2025-10-12 00:23:16.982568 | controller -> localhost | |+o+=.            |
2025-10-12 00:23:16.982608 | controller -> localhost | |+==+. o          |
2025-10-12 00:23:16.982648 | controller -> localhost | |=o=O==..         |
2025-10-12 00:23:16.982747 | controller -> localhost | |+.=oB+o          |
2025-10-12 00:23:16.982793 | controller -> localhost | |.+ o  . S        |
2025-10-12 00:23:16.982834 | controller -> localhost | |+.. .  o         |
2025-10-12 00:23:16.982874 | controller -> localhost | |=+ .    .        |
2025-10-12 00:23:16.982914 | controller -> localhost | |O.o  E           |
2025-10-12 00:23:16.982954 | controller -> localhost | |*= .o .          |
2025-10-12 00:23:16.982993 | controller -> localhost | +----[SHA256]-----+
2025-10-12 00:23:16.983083 | controller -> localhost | ok: Runtime: 0:00:00.007548
2025-10-12 00:23:16.996744 | 
2025-10-12 00:23:16.996885 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-12 00:23:17.035895 | controller | ok
2025-10-12 00:23:17.052224 | controller | included: /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-12 00:23:17.067563 | 
2025-10-12 00:23:17.067646 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-12 00:23:17.092696 | controller | skipping: Conditional result was False
2025-10-12 00:23:17.101325 | 
2025-10-12 00:23:17.101490 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-12 00:23:17.565339 | controller | changed
2025-10-12 00:23:17.577830 | 
2025-10-12 00:23:17.577986 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-12 00:23:17.973127 | controller | ok
2025-10-12 00:23:17.987582 | 
2025-10-12 00:23:17.987760 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-12 00:23:19.323997 | controller | changed
2025-10-12 00:23:19.336846 | 
2025-10-12 00:23:19.336991 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-12 00:23:20.672072 | controller | changed
2025-10-12 00:23:20.684315 | 
2025-10-12 00:23:20.684445 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-12 00:23:20.711187 | controller | skipping: Conditional result was False
2025-10-12 00:23:20.724771 | 
2025-10-12 00:23:20.724916 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-12 00:23:20.955481 | controller -> localhost | changed
2025-10-12 00:23:20.979635 | 
2025-10-12 00:23:20.979797 | TASK [add-build-sshkey : Add back temp key]
2025-10-12 00:23:21.282629 | controller -> localhost | Identity added: /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/work/33afdf37fe2045ec850525d6fafdfded_id_ecdsa (zuul-build-sshkey)
2025-10-12 00:23:21.283185 | controller -> localhost | ok: Runtime: 0:00:00.008823
2025-10-12 00:23:21.297723 | 
2025-10-12 00:23:21.297858 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-12 00:23:21.625078 | controller | ok
2025-10-12 00:23:21.636700 | 
2025-10-12 00:23:21.636834 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-12 00:23:21.674895 | controller | skipping: Conditional result was False
2025-10-12 00:23:21.698613 | 
2025-10-12 00:23:21.698781 | TASK [include_role : remove-zuul-sshkey]
2025-10-12 00:23:21.725887 | controller | skipping: Conditional result was False
2025-10-12 00:23:21.738980 | 
2025-10-12 00:23:21.739120 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-12 00:23:22.069370 | controller | ok: "logs"
2025-10-12 00:23:22.069685 | controller | ok: All items complete
2025-10-12 00:23:22.069721 | 
2025-10-12 00:23:22.392844 | controller | ok: "artifacts"
2025-10-12 00:23:22.649349 | controller | ok: "docs"
2025-10-12 00:23:22.667587 | 
2025-10-12 00:23:22.667805 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-12 00:23:23.012569 | controller | changed: "logs"
2025-10-12 00:23:23.311015 | controller | changed: "artifacts"
2025-10-12 00:23:23.599452 | controller | changed: "docs"
2025-10-12 00:23:23.645161 | 
2025-10-12 00:23:23.645245 | PLAY RECAP
2025-10-12 00:23:23.645304 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-12 00:23:23.645341 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-12 00:23:23.645365 | 
2025-10-12 00:23:23.819904 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-12 00:23:23.822384 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-12 00:23:24.414955 | 
2025-10-12 00:23:24.415057 | PLAY [all]
2025-10-12 00:23:24.435505 | 
2025-10-12 00:23:24.435601 | TASK [Install binary dependencies]
2025-10-12 00:23:24.507458 | controller | ok
2025-10-12 00:23:24.533083 | 
2025-10-12 00:23:24.533188 | TASK [bindep : Include find tasks]
2025-10-12 00:23:24.579522 | controller | ok
2025-10-12 00:23:24.592888 | controller | included: /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-12 00:23:24.600976 | 
2025-10-12 00:23:24.601060 | TASK [bindep : Look for bindep.txt]
2025-10-12 00:23:25.166772 | controller | ok
2025-10-12 00:23:25.180204 | 
2025-10-12 00:23:25.180347 | TASK [bindep : Define bindep_file fact]
2025-10-12 00:23:25.208829 | controller | skipping: Conditional result was False
2025-10-12 00:23:25.222697 | 
2025-10-12 00:23:25.222892 | TASK [bindep : Look for other-requirements.txt]
2025-10-12 00:23:25.558415 | controller | ok
2025-10-12 00:23:25.570181 | 
2025-10-12 00:23:25.570346 | TASK [bindep : Define bindep_file fact]
2025-10-12 00:23:25.609737 | controller | skipping: Conditional result was False
2025-10-12 00:23:25.625390 | 
2025-10-12 00:23:25.625583 | TASK [bindep : Look for bindep fallback file]
2025-10-12 00:23:25.665542 | controller | skipping: Conditional result was False
2025-10-12 00:23:25.680184 | 
2025-10-12 00:23:25.680336 | TASK [bindep : Define bindep_file fact]
2025-10-12 00:23:25.707573 | controller | skipping: Conditional result was False
2025-10-12 00:23:25.721141 | 
2025-10-12 00:23:25.721277 | TASK [bindep : Include bindep tasks]
2025-10-12 00:23:25.758544 | controller | skipping: Conditional result was False
2025-10-12 00:23:25.775016 | 
2025-10-12 00:23:25.775154 | TASK [bindep : Include install tasks]
2025-10-12 00:23:25.822946 | controller | skipping: Conditional result was False
2025-10-12 00:23:25.831511 | 
2025-10-12 00:23:25.831600 | LOOP [bindep : Include package tasks]
2025-10-12 00:23:25.893831 | 
2025-10-12 00:23:25.894043 | TASK [Run test-setup role]
2025-10-12 00:23:25.914245 | controller | ok
2025-10-12 00:23:25.933821 | 
2025-10-12 00:23:25.933949 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-12 00:23:26.823911 | controller | ok
2025-10-12 00:23:26.830019 | 
2025-10-12 00:23:26.830080 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-12 00:23:26.969874 | controller | skipping: Conditional result was False
2025-10-12 00:23:27.023357 | 
2025-10-12 00:23:27.023432 | PLAY RECAP
2025-10-12 00:23:27.023488 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-12 00:23:27.023516 | 
2025-10-12 00:23:27.124620 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-12 00:23:27.125454 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-12 00:23:27.718852 | 
2025-10-12 00:23:27.718982 | PLAY [controller]
2025-10-12 00:23:27.741084 | 
2025-10-12 00:23:27.741161 | TASK [Create the /root directory]
2025-10-12 00:23:28.428859 | controller | ok
2025-10-12 00:23:28.434511 | 
2025-10-12 00:23:28.434580 | TASK [Install glibc-langpack-en]
2025-10-12 00:23:36.526763 | controller | ok: Nothing to do
2025-10-12 00:23:36.538629 | 
2025-10-12 00:23:36.538790 | TASK [Ensure controller directory exists]
2025-10-12 00:23:37.045968 | controller | changed
2025-10-12 00:23:37.057957 | 
2025-10-12 00:23:37.058107 | TASK [Install container runtime]
2025-10-12 00:23:37.128870 | controller | ok
2025-10-12 00:23:37.186060 | 
2025-10-12 00:23:37.186190 | LOOP [ensure-podman : Find distribution installation]
2025-10-12 00:23:37.228221 | controller | ok: "/var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-12 00:23:37.249059 | controller | included: /var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-12 00:23:37.262829 | 
2025-10-12 00:23:37.262970 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-12 00:24:56.006904 | controller | changed
2025-10-12 00:24:56.020585 | 
2025-10-12 00:24:56.020752 | TASK [ensure-podman : Fetch podman version]
2025-10-12 00:24:56.758222 | controller | Client:       Podman Engine
2025-10-12 00:24:56.758301 | controller | Version:      4.6.2
2025-10-12 00:24:56.758331 | controller | API Version:  4.6.2
2025-10-12 00:24:56.758358 | controller | Go Version:   go1.19.12
2025-10-12 00:24:56.758394 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-12 00:24:56.758421 | controller | OS/Arch:      linux/amd64
2025-10-12 00:24:57.177149 | controller | ok: Runtime: 0:00:00.217871
2025-10-12 00:24:57.190749 | 
2025-10-12 00:24:57.190899 | TASK [ensure-podman : Print podman version installed]
2025-10-12 00:24:57.229778 | Podman version: Client:       Podman Engine
2025-10-12 00:24:57.230005 | Version:      4.6.2
2025-10-12 00:24:57.230065 | API Version:  4.6.2
2025-10-12 00:24:57.230111 | Go Version:   go1.19.12
2025-10-12 00:24:57.230152 | Built:        Mon Aug 28 19:38:31 2023
2025-10-12 00:24:57.230193 | OS/Arch:      linux/amd64
2025-10-12 00:24:57.241956 | 
2025-10-12 00:24:57.242082 | TASK [ensure-podman : Validate podman engine]
2025-10-12 00:24:57.385552 | controller | skipping: Conditional result was False
2025-10-12 00:24:57.393847 | 
2025-10-12 00:24:57.393934 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-12 00:24:57.418659 | controller | skipping: Conditional result was False
2025-10-12 00:24:57.432979 | 
2025-10-12 00:24:57.433063 | TASK [Ensure python3.8 is present]
2025-10-12 00:24:57.457781 | controller | skipping: Conditional result was False
2025-10-12 00:24:57.465365 | 
2025-10-12 00:24:57.465449 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-12 00:24:57.497719 | controller | ok
2025-10-12 00:24:57.522554 | 
2025-10-12 00:24:57.522640 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-12 00:25:01.397825 | controller | ok: Nothing to do
2025-10-12 00:25:01.409420 | 
2025-10-12 00:25:01.409550 | TASK [our-ensure-python : Also install python3-devel]
2025-10-12 00:25:15.430150 | controller | changed
2025-10-12 00:25:15.454915 | 
2025-10-12 00:25:15.455068 | TASK [Run ensure-virtualenv role]
2025-10-12 00:25:15.485946 | controller | ok
2025-10-12 00:25:15.519817 | 
2025-10-12 00:25:15.519913 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-12 00:25:15.905248 | controller | /usr/bin/virtualenv
2025-10-12 00:25:16.160231 | controller | ok: Runtime: 0:00:00.004524
2025-10-12 00:25:16.173376 | 
2025-10-12 00:25:16.173520 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-12 00:25:16.214638 | controller | skipping: Conditional result was False
2025-10-12 00:25:16.215185 | controller | ok: All items complete
2025-10-12 00:25:16.215247 | 
2025-10-12 00:25:16.245541 | 
2025-10-12 00:25:16.245734 | TASK [Find the full path of the Python interpreter]
2025-10-12 00:25:16.734270 | controller | /usr/bin/python3
2025-10-12 00:25:16.944976 | controller | ok
2025-10-12 00:25:16.956985 | 
2025-10-12 00:25:16.957181 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-12 00:25:18.390687 | controller | created virtual environment CPython3.11.0.final.0-64 in 744ms
2025-10-12 00:25:18.445865 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-12 00:25:18.445920 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv)
2025-10-12 00:25:18.445939 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-12 00:25:18.445961 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-12 00:25:18.637446 | controller | changed
2025-10-12 00:25:18.650141 | 
2025-10-12 00:25:18.650287 | TASK [Set selinux package]
2025-10-12 00:25:18.689921 | controller | ok
2025-10-12 00:25:18.700737 | 
2025-10-12 00:25:18.700864 | TASK [Set selinux package (Fedora)]
2025-10-12 00:25:18.749576 | controller | ok
2025-10-12 00:25:18.760791 | 
2025-10-12 00:25:18.760922 | TASK [Install selinux into virtualenv]
2025-10-12 00:25:21.423809 | controller | Collecting selinux-please-lie-to-me
2025-10-12 00:25:21.525419 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-12 00:25:22.061773 | controller | Collecting setuptools<50.0.0
2025-10-12 00:25:22.078814 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-12 00:25:22.204515 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00
2025-10-12 00:25:22.358574 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-12 00:25:22.358900 | controller |   Attempting uninstall: setuptools
2025-10-12 00:25:22.363881 | controller |     Found existing installation: setuptools 62.6.0
2025-10-12 00:25:22.477273 | controller |     Uninstalling setuptools-62.6.0:
2025-10-12 00:25:22.492600 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-12 00:25:23.236583 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-12 00:25:23.450079 | controller |
2025-10-12 00:25:23.670347 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-12 00:25:23.670394 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-12 00:25:23.938972 | controller | ok: Runtime: 0:00:04.414938
2025-10-12 00:25:23.952779 | 
2025-10-12 00:25:23.953052 | TASK [Install pytest-forked into virtualenv]
2025-10-12 00:25:25.186724 | controller | Collecting pytest-forked
2025-10-12 00:25:25.280613 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-12 00:25:25.360698 | controller | Collecting py
2025-10-12 00:25:25.375251 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-12 00:25:25.413974 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.8 MB/s eta 0:00:00
2025-10-12 00:25:25.590571 | controller | Collecting pytest>=3.10
2025-10-12 00:25:25.611638 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-12 00:25:25.681240 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.4 MB/s eta 0:00:00
2025-10-12 00:25:25.736491 | controller | Collecting iniconfig>=1
2025-10-12 00:25:25.749559 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-12 00:25:25.814669 | controller | Collecting packaging>=20
2025-10-12 00:25:25.826610 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-12 00:25:25.840350 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.3 MB/s eta 0:00:00
2025-10-12 00:25:25.886971 | controller | Collecting pluggy<2,>=1.5
2025-10-12 00:25:25.899104 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-12 00:25:25.976604 | controller | Collecting pygments>=2.7.2
2025-10-12 00:25:25.992910 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-12 00:25:26.113083 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.4 MB/s eta 0:00:00
2025-10-12 00:25:26.247393 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-12 00:25:28.510611 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-10-12 00:25:28.526884 | controller |
2025-10-12 00:25:28.726573 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-12 00:25:28.726620 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-12 00:25:29.170249 | controller | ok: Runtime: 0:00:04.273793
2025-10-12 00:25:29.178125 | 
2025-10-12 00:25:29.178213 | TASK [Update pip]
2025-10-12 00:25:30.308729 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-12 00:25:30.584307 | controller | Collecting pip
2025-10-12 00:25:30.679814 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-12 00:25:30.891857 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.4 MB/s eta 0:00:00
2025-10-12 00:25:31.058322 | controller | Installing collected packages: pip
2025-10-12 00:25:31.058632 | controller |   Attempting uninstall: pip
2025-10-12 00:25:31.066684 | controller |     Found existing installation: pip 22.2.2
2025-10-12 00:25:31.347599 | controller |     Uninstalling pip-22.2.2:
2025-10-12 00:25:31.377824 | controller |       Successfully uninstalled pip-22.2.2
2025-10-12 00:25:33.133545 | controller | Successfully installed pip-25.2
2025-10-12 00:25:33.829946 | controller | ok: Runtime: 0:00:03.625496
2025-10-12 00:25:33.835501 | 
2025-10-12 00:25:33.835561 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-12 00:25:34.351169 | controller | changed
2025-10-12 00:25:34.356258 | 
2025-10-12 00:25:34.356321 | TASK [Install ansible into virtualenv]
2025-10-12 00:25:35.501009 | controller | Processing ./src/github.com/ansible/ansible
2025-10-12 00:25:35.507559 | controller |   Installing build dependencies: started
2025-10-12 00:25:37.428240 | controller |   Installing build dependencies: finished with status 'done'
2025-10-12 00:25:38.974850 | controller |   Getting requirements to build wheel: started
2025-10-12 00:25:38.974920 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-12 00:25:38.976587 | controller |   Preparing metadata (pyproject.toml): started
2025-10-12 00:25:39.916867 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-12 00:25:39.921845 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-10-12 00:25:39.926859 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-12 00:25:40.511624 | controller | ERROR
2025-10-12 00:25:40.512035 | controller | {
2025-10-12 00:25:40.512098 | controller |   "delta": "0:00:05.305594",
2025-10-12 00:25:40.512140 | controller |   "end": "2025-10-12 00:25:40.083970",
2025-10-12 00:25:40.512178 | controller |   "msg": "non-zero return code",
2025-10-12 00:25:40.512230 | controller |   "rc": 1,
2025-10-12 00:25:40.512268 | controller |   "start": "2025-10-12 00:25:34.778376"
2025-10-12 00:25:40.512302 | controller | }
failure
2025-10-12 00:25:40.515415 | 
2025-10-12 00:25:40.515472 | PLAY RECAP
2025-10-12 00:25:40.515518 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-12 00:25:40.515540 | 
2025-10-12 00:25:40.615991 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-12 00:25:40.618003 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-12 00:25:41.186831 | 
2025-10-12 00:25:41.186946 | PLAY [all]
2025-10-12 00:25:41.207498 | 
2025-10-12 00:25:41.207588 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-12 00:25:42.000940 | controller | changed: non-zero return code
2025-10-12 00:25:42.017365 | 
2025-10-12 00:25:42.017535 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-12 00:25:42.044555 | controller | skipping: Conditional result was False
2025-10-12 00:25:42.058328 | 
2025-10-12 00:25:42.058478 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-12 00:25:42.099733 | 
2025-10-12 00:25:42.099977 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-12 00:25:42.140984 | 
2025-10-12 00:25:42.141240 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-12 00:25:42.168742 | controller | skipping: Conditional result was False
2025-10-12 00:25:42.181884 | 
2025-10-12 00:25:42.182029 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-12 00:25:42.225206 | 
2025-10-12 00:25:42.225470 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-12 00:25:42.252655 | controller | skipping: Conditional result was False
2025-10-12 00:25:42.266412 | 
2025-10-12 00:25:42.266554 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-12 00:25:42.293779 | controller | skipping: Conditional result was False
2025-10-12 00:25:42.306650 | 
2025-10-12 00:25:42.306820 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-12 00:25:42.334101 | controller | skipping: Conditional result was False
2025-10-12 00:25:42.380544 | 
2025-10-12 00:25:42.380622 | PLAY RECAP
2025-10-12 00:25:42.380716 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-12 00:25:42.380760 | 
2025-10-12 00:25:42.479841 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-12 00:25:42.481726 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-12 00:25:43.053714 | 
2025-10-12 00:25:43.053822 | PLAY [all:!appliance*]
2025-10-12 00:25:43.074639 | 
2025-10-12 00:25:43.074731 | TASK [unregister the node]
2025-10-12 00:25:43.209390 | controller | skipping: Conditional result was False
2025-10-12 00:25:43.222574 | 
2025-10-12 00:25:43.222771 | TASK [include_role : fetch-output]
2025-10-12 00:25:43.261354 | controller | ok
2025-10-12 00:25:43.296287 | 
2025-10-12 00:25:43.296398 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-12 00:25:43.342155 | controller | skipping: Conditional result was False
2025-10-12 00:25:43.354780 | 
2025-10-12 00:25:43.355058 | TASK [fetch-output : Set log path for single node]
2025-10-12 00:25:43.394292 | controller | ok
2025-10-12 00:25:43.406800 | 
2025-10-12 00:25:43.406955 | LOOP [fetch-output : Ensure local output dirs]
2025-10-12 00:25:43.816118 | controller -> localhost | ok: "/var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/work/logs"
2025-10-12 00:25:44.018648 | controller -> localhost | changed: "/var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/work/artifacts"
2025-10-12 00:25:44.231317 | controller -> localhost | changed: "/var/lib/zuul/builds/33afdf37fe2045ec850525d6fafdfded/work/docs"
2025-10-12 00:25:44.255583 | 
2025-10-12 00:25:44.255814 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-12 00:25:45.469882 | controller | changed:
2025-10-12 00:25:45.470209 | controller | .d..t...... ./
2025-10-12 00:25:45.470268 | controller | cd+++++++++ controller/
2025-10-12 00:25:45.470335 | controller | changed: All items complete
2025-10-12 00:25:45.470379 | 
2025-10-12 00:25:46.534572 | controller | changed: .d..t...... ./
2025-10-12 00:25:47.689151 | controller | changed: .d..t...... ./
2025-10-12 00:25:47.724814 | 
2025-10-12 00:25:47.725127 | TASK [include_role : fetch-output-openshift]
2025-10-12 00:25:47.752117 | controller | skipping: Conditional result was False
2025-10-12 00:25:47.764709 | 
2025-10-12 00:25:47.764848 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-12 00:25:47.816876 | controller | skipping: Conditional result was False
2025-10-12 00:25:47.827696 | controller | skipping: Conditional result was False
2025-10-12 00:25:47.885890 | 
2025-10-12 00:25:47.886024 | PLAY [localhost]
2025-10-12 00:25:47.902852 | 
2025-10-12 00:25:47.902931 | TASK [Run Zuul manifest role]
2025-10-12 00:25:47.933314 | localhost | ok
2025-10-12 00:25:47.951262 | 
2025-10-12 00:25:47.951353 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-12 00:25:48.445536 | localhost | changed
2025-10-12 00:25:48.456184 | 
2025-10-12 00:25:48.456318 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-12 00:25:48.503618 | localhost | ok
2025-10-12 00:25:48.521326 | 
2025-10-12 00:25:48.521456 | TASK [Set zuul-log-path fact]
2025-10-12 00:25:48.548445 | localhost | ok
2025-10-12 00:25:48.572856 | 
2025-10-12 00:25:48.572943 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-12 00:25:48.605400 | localhost | ok
2025-10-12 00:25:48.617454 | 
2025-10-12 00:25:48.617534 | LOOP [Run upload-logs-swift role]
2025-10-12 00:25:48.665322 | localhost | Output suppressed because no_log was given
2025-10-12 00:25:48.698298 | 
2025-10-12 00:25:48.698385 | TASK [Set zuul-log-path fact]
2025-10-12 00:25:48.744947 | localhost | skipping: Conditional result was False
2025-10-12 00:25:48.751548 | 
2025-10-12 00:25:48.751635 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-12 00:25:49.239993 | localhost -> localhost | ok: Runtime: 0:00:00.008888
2025-10-12 00:25:49.251385 | 
2025-10-12 00:25:49.251555 | TASK [upload-logs-swift : Upload logs to swift]