2025-10-05 00:11:48.115228 | Job console starting...
2025-10-05 00:11:48.125051 | Updating repositories
2025-10-05 00:11:48.234025 | Preparing job workspace
2025-10-05 00:11:51.728441 | Running Ansible setup...
2025-10-05 00:11:57.725895 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-05 00:11:58.398831 | 
2025-10-05 00:11:58.398956 | PLAY [localhost]
2025-10-05 00:11:58.407567 | 
2025-10-05 00:11:58.407647 | TASK [Gathering Facts]
2025-10-05 00:11:59.470381 | localhost | ok
2025-10-05 00:11:59.488628 | 
2025-10-05 00:11:59.488759 | TASK [Setup log path fact]
2025-10-05 00:11:59.510036 | localhost | ok
2025-10-05 00:11:59.529782 | 
2025-10-05 00:11:59.529923 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-05 00:11:59.561061 | localhost | ok
2025-10-05 00:11:59.573075 | 
2025-10-05 00:11:59.573252 | TASK [emit-job-header : Print job information]
2025-10-05 00:11:59.603827 | # Job Information
2025-10-05 00:11:59.604004 | Ansible Version: 2.15.12
2025-10-05 00:11:59.604045 | Job: ansible-test-sanity-docker-devel
2025-10-05 00:11:59.604074 | Pipeline: periodic
2025-10-05 00:11:59.604098 | Executor: ze03.softwarefactory-project.io
2025-10-05 00:11:59.604122 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-05 00:11:59.604149 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/a66/ansible/a663376e1fcb48a89b4792135e2b2e40/
2025-10-05 00:11:59.604175 | Event ID: 82198ffb092345eeb6b1fdd59cdb0848
2025-10-05 00:11:59.609126 | 
2025-10-05 00:11:59.609204 | LOOP [emit-job-header : Print node information]
2025-10-05 00:11:59.710960 | localhost | ok:
2025-10-05 00:11:59.711153 | localhost | # Node Information
2025-10-05 00:11:59.711192 | localhost | Inventory Hostname: controller
2025-10-05 00:11:59.711218 | localhost | Hostname: ip-172-16-165-232
2025-10-05 00:11:59.711243 | localhost | Username: zuul-worker
2025-10-05 00:11:59.711269 | localhost | Distro: Fedora 37
2025-10-05 00:11:59.711293 | localhost | Provider: ansible-us-east-2
2025-10-05 00:11:59.711317 | localhost | Region: us-east-2
2025-10-05 00:11:59.711345 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-05 00:11:59.711372 | localhost | Product Name: t3.small
2025-10-05 00:11:59.711398 | localhost | Interface IP: 3.141.18.4
2025-10-05 00:11:59.728354 | 
2025-10-05 00:11:59.728561 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-05 00:12:00.131361 | localhost -> localhost | changed
2025-10-05 00:12:00.139441 | 
2025-10-05 00:12:00.139551 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-05 00:12:01.111524 | localhost -> localhost | changed
2025-10-05 00:12:01.141765 | 
2025-10-05 00:12:01.141888 | PLAY [all:!appliance*]
2025-10-05 00:12:01.166066 | 
2025-10-05 00:12:01.166207 | TASK [include_role : start-zuul-console]
2025-10-05 00:12:01.186162 | controller | ok
2025-10-05 00:12:01.200154 | 
2025-10-05 00:12:01.200263 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-05 00:12:02.889869 | controller | ok
2025-10-05 00:12:02.905245 | 
2025-10-05 00:12:02.905361 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-05 00:12:04.703135 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-05 00:12:04.720967 | 
2025-10-05 00:12:04.721140 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-05 00:12:04.872481 | controller | skipping: Conditional result was False
2025-10-05 00:12:04.887081 | 
2025-10-05 00:12:04.887288 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-05 00:12:04.925845 | controller | skipping: Conditional result was False
2025-10-05 00:12:04.942456 | 
2025-10-05 00:12:04.942629 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-05 00:12:04.957506 | controller | skipping: Conditional result was False
2025-10-05 00:12:04.967392 | 
2025-10-05 00:12:04.967540 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-05 00:12:04.995290 | controller | skipping: Conditional result was False
2025-10-05 00:12:05.004839 | 
2025-10-05 00:12:05.004984 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-05 00:12:05.030947 | controller | skipping: Conditional result was False
2025-10-05 00:12:05.041299 | 
2025-10-05 00:12:05.041424 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-05 00:12:05.067645 | controller | skipping: Conditional result was False
2025-10-05 00:12:05.086077 | 
2025-10-05 00:12:05.086237 | TASK [Disable Fedora Modular]
2025-10-05 00:12:05.817265 | controller | changed
2025-10-05 00:12:05.826212 | 
2025-10-05 00:12:05.826338 | TASK [Enable EPEL]
2025-10-05 00:12:05.852062 | controller | skipping: Conditional result was False
2025-10-05 00:12:05.861970 | 
2025-10-05 00:12:05.862116 | TASK [Register the RHEL node]
2025-10-05 00:12:06.026470 | 
2025-10-05 00:12:06.026672 | TASK [Show the subscription-manager status]
2025-10-05 00:12:06.205408 | controller | skipping: Conditional result was False
2025-10-05 00:12:06.214263 | 
2025-10-05 00:12:06.214372 | TASK [Enable EPEL on RHEL]
2025-10-05 00:12:06.362637 | controller | skipping: Conditional result was False
2025-10-05 00:12:06.368846 | 
2025-10-05 00:12:06.368964 | TASK [Install git and tox]
2025-10-05 00:13:39.028896 | controller | changed
2025-10-05 00:13:39.043304 | 
2025-10-05 00:13:39.043498 | TASK [include_role : prepare-workspace]
2025-10-05 00:13:39.066493 | controller | ok
2025-10-05 00:13:39.088396 | 
2025-10-05 00:13:39.088499 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-05 00:13:39.664217 | controller | ok
2025-10-05 00:13:39.678292 | 
2025-10-05 00:13:39.678452 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-05 00:13:52.555554 | controller | Output suppressed because no_log was given
2025-10-05 00:13:52.572919 | 
2025-10-05 00:13:52.573082 | TASK [include_role : prepare-workspace-openshift]
2025-10-05 00:13:52.600373 | controller | skipping: Conditional result was False
2025-10-05 00:13:52.669519 | 
2025-10-05 00:13:52.669598 | PLAY [all:!appliance]
2025-10-05 00:13:52.686130 | 
2025-10-05 00:13:52.686234 | TASK [Run add-build-sshkey role (RSA)]
2025-10-05 00:13:52.716681 | controller | ok
2025-10-05 00:13:52.733259 | 
2025-10-05 00:13:52.733386 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-05 00:13:53.013387 | controller -> localhost | ok
2025-10-05 00:13:53.020343 | 
2025-10-05 00:13:53.020448 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-05 00:13:53.044359 | controller | ok
2025-10-05 00:13:53.062871 | controller | included: /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-05 00:13:53.071182 | 
2025-10-05 00:13:53.071312 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-05 00:13:53.575704 | controller -> localhost | Generating public/private rsa key pair.
2025-10-05 00:13:53.576139 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/work/a663376e1fcb48a89b4792135e2b2e40_id_rsa.
2025-10-05 00:13:53.576207 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/work/a663376e1fcb48a89b4792135e2b2e40_id_rsa.pub.
2025-10-05 00:13:53.576257 | controller -> localhost | The key fingerprint is:
2025-10-05 00:13:53.576302 | controller -> localhost | SHA256:WPzXPoriMNlGlU/6OfSfxO9Wq/tyEWNNWjoZevEBmsw zuul-build-sshkey
2025-10-05 00:13:53.576345 | controller -> localhost | The key's randomart image is:
2025-10-05 00:13:53.576388 | controller -> localhost | +---[RSA 2048]----+
2025-10-05 00:13:53.576428 | controller -> localhost | |             ..  |
2025-10-05 00:13:53.576470 | controller -> localhost | |       .  o.o o.o|
2025-10-05 00:13:53.576511 | controller -> localhost | |        o oE.. Xo|
2025-10-05 00:13:53.576552 | controller -> localhost | |       o o +..*+o|
2025-10-05 00:13:53.576592 | controller -> localhost | |      . S o +.o.o|
2025-10-05 00:13:53.576651 | controller -> localhost | |       +   + +...|
2025-10-05 00:13:53.576700 | controller -> localhost | |      + o   + +o+|
2025-10-05 00:13:53.577516 | controller -> localhost | |       +.  . +.=+|
2025-10-05 00:13:53.577570 | controller -> localhost | |       .... .o*=+|
2025-10-05 00:13:53.577619 | controller -> localhost | +----[SHA256]-----+
2025-10-05 00:13:53.577719 | controller -> localhost | ok: Runtime: 0:00:00.114142
2025-10-05 00:13:53.594722 | 
2025-10-05 00:13:53.594943 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-05 00:13:53.646977 | controller | ok
2025-10-05 00:13:53.664653 | controller | included: /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-05 00:13:53.677928 | 
2025-10-05 00:13:53.678019 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-05 00:13:53.712872 | controller | skipping: Conditional result was False
2025-10-05 00:13:53.720956 | 
2025-10-05 00:13:53.721044 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-05 00:13:54.420612 | controller | changed
2025-10-05 00:13:54.437687 | 
2025-10-05 00:13:54.437898 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-05 00:13:54.878807 | controller | ok
2025-10-05 00:13:54.892350 | 
2025-10-05 00:13:54.892527 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-05 00:13:56.228288 | controller | changed
2025-10-05 00:13:56.242168 | 
2025-10-05 00:13:56.242484 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-05 00:13:57.564451 | controller | changed
2025-10-05 00:13:57.572410 | 
2025-10-05 00:13:57.572518 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-05 00:13:57.597511 | controller | skipping: Conditional result was False
2025-10-05 00:13:57.606659 | 
2025-10-05 00:13:57.606825 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-05 00:13:58.023683 | controller -> localhost | changed
2025-10-05 00:13:58.049440 | 
2025-10-05 00:13:58.049621 | TASK [add-build-sshkey : Add back temp key]
2025-10-05 00:13:58.342681 | controller -> localhost | Identity added: /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/work/a663376e1fcb48a89b4792135e2b2e40_id_rsa (zuul-build-sshkey)
2025-10-05 00:13:58.343015 | controller -> localhost | ok: Runtime: 0:00:00.009924
2025-10-05 00:13:58.350157 | 
2025-10-05 00:13:58.350228 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-05 00:13:58.912333 | controller | ok
2025-10-05 00:13:58.919807 | 
2025-10-05 00:13:58.919889 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-05 00:13:58.956156 | controller | skipping: Conditional result was False
2025-10-05 00:13:58.972325 | 
2025-10-05 00:13:58.972552 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-05 00:13:58.996069 | controller | ok
2025-10-05 00:13:59.018712 | 
2025-10-05 00:13:59.018845 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-05 00:13:59.279141 | controller -> localhost | ok
2025-10-05 00:13:59.288007 | 
2025-10-05 00:13:59.288131 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-05 00:13:59.320976 | controller | ok
2025-10-05 00:13:59.339298 | controller | included: /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-05 00:13:59.345445 | 
2025-10-05 00:13:59.345518 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-05 00:13:59.635334 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-05 00:13:59.635521 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/work/a663376e1fcb48a89b4792135e2b2e40_id_ecdsa.
2025-10-05 00:13:59.635551 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/work/a663376e1fcb48a89b4792135e2b2e40_id_ecdsa.pub.
2025-10-05 00:13:59.635586 | controller -> localhost | The key fingerprint is:
2025-10-05 00:13:59.635606 | controller -> localhost | SHA256:VKW5aZmjzU+UIi4VRyalp0V0VLVxdl2AeXwOvRnNgcY zuul-build-sshkey
2025-10-05 00:13:59.635630 | controller -> localhost | The key's randomart image is:
2025-10-05 00:13:59.635649 | controller -> localhost | +---[ECDSA 521]---+
2025-10-05 00:13:59.635669 | controller -> localhost | |        .oBo==+B@|
2025-10-05 00:13:59.635687 | controller -> localhost | |         B +oE+o@|
2025-10-05 00:13:59.635706 | controller -> localhost | |        + * .. =+|
2025-10-05 00:13:59.635746 | controller -> localhost | |       . * = . o.|
2025-10-05 00:13:59.635772 | controller -> localhost | |        S O o    |
2025-10-05 00:13:59.635791 | controller -> localhost | |       o * +     |
2025-10-05 00:13:59.635809 | controller -> localhost | |      . o o .    |
2025-10-05 00:13:59.635826 | controller -> localhost | |       .   o     |
2025-10-05 00:13:59.635845 | controller -> localhost | |            .    |
2025-10-05 00:13:59.635863 | controller -> localhost | +----[SHA256]-----+
2025-10-05 00:13:59.635911 | controller -> localhost | ok: Runtime: 0:00:00.010916
2025-10-05 00:13:59.643014 | 
2025-10-05 00:13:59.643122 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-05 00:13:59.678512 | controller | ok
2025-10-05 00:13:59.694440 | controller | included: /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-05 00:13:59.711006 | 
2025-10-05 00:13:59.711177 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-05 00:13:59.736143 | controller | skipping: Conditional result was False
2025-10-05 00:13:59.744244 | 
2025-10-05 00:13:59.744382 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-05 00:14:00.496430 | controller | changed
2025-10-05 00:14:00.503876 | 
2025-10-05 00:14:00.504133 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-05 00:14:00.929612 | controller | ok
2025-10-05 00:14:00.938279 | 
2025-10-05 00:14:00.938412 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-05 00:14:03.531234 | controller | changed
2025-10-05 00:14:03.538916 | 
2025-10-05 00:14:03.539056 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-05 00:14:04.997852 | controller | changed
2025-10-05 00:14:05.006342 | 
2025-10-05 00:14:05.006486 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-05 00:14:05.033058 | controller | skipping: Conditional result was False
2025-10-05 00:14:05.041592 | 
2025-10-05 00:14:05.041751 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-05 00:14:05.333552 | controller -> localhost | changed
2025-10-05 00:14:05.347704 | 
2025-10-05 00:14:05.347860 | TASK [add-build-sshkey : Add back temp key]
2025-10-05 00:14:05.726901 | controller -> localhost | Identity added: /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/work/a663376e1fcb48a89b4792135e2b2e40_id_ecdsa (zuul-build-sshkey)
2025-10-05 00:14:05.727114 | controller -> localhost | ok: Runtime: 0:00:00.024988
2025-10-05 00:14:05.735847 | 
2025-10-05 00:14:05.735991 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-05 00:14:06.124013 | controller | ok
2025-10-05 00:14:06.129665 | 
2025-10-05 00:14:06.129754 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-05 00:14:06.154031 | controller | skipping: Conditional result was False
2025-10-05 00:14:06.167875 | 
2025-10-05 00:14:06.167989 | TASK [include_role : remove-zuul-sshkey]
2025-10-05 00:14:06.193070 | controller | skipping: Conditional result was False
2025-10-05 00:14:06.201719 | 
2025-10-05 00:14:06.201849 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-05 00:14:06.540121 | controller | ok: "logs"
2025-10-05 00:14:06.540409 | controller | ok: All items complete
2025-10-05 00:14:06.540449 | 
2025-10-05 00:14:06.861909 | controller | ok: "artifacts"
2025-10-05 00:14:07.150190 | controller | ok: "docs"
2025-10-05 00:14:07.178516 | 
2025-10-05 00:14:07.178657 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-05 00:14:07.528672 | controller | changed: "logs"
2025-10-05 00:14:07.821319 | controller | changed: "artifacts"
2025-10-05 00:14:08.117348 | controller | changed: "docs"
2025-10-05 00:14:08.153591 | 
2025-10-05 00:14:08.153684 | PLAY RECAP
2025-10-05 00:14:08.153744 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-05 00:14:08.153774 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-05 00:14:08.153794 | 
2025-10-05 00:14:08.266933 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-05 00:14:08.267802 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-05 00:14:08.834670 | 
2025-10-05 00:14:08.834816 | PLAY [all]
2025-10-05 00:14:08.856372 | 
2025-10-05 00:14:08.856483 | TASK [Install binary dependencies]
2025-10-05 00:14:08.953348 | controller | ok
2025-10-05 00:14:08.973258 | 
2025-10-05 00:14:08.973397 | TASK [bindep : Include find tasks]
2025-10-05 00:14:09.006086 | controller | ok
2025-10-05 00:14:09.013914 | controller | included: /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-05 00:14:09.020035 | 
2025-10-05 00:14:09.020099 | TASK [bindep : Look for bindep.txt]
2025-10-05 00:14:09.594313 | controller | ok
2025-10-05 00:14:09.608494 | 
2025-10-05 00:14:09.608694 | TASK [bindep : Define bindep_file fact]
2025-10-05 00:14:09.635884 | controller | skipping: Conditional result was False
2025-10-05 00:14:09.648935 | 
2025-10-05 00:14:09.649130 | TASK [bindep : Look for other-requirements.txt]
2025-10-05 00:14:09.969452 | controller | ok
2025-10-05 00:14:09.974961 | 
2025-10-05 00:14:09.975056 | TASK [bindep : Define bindep_file fact]
2025-10-05 00:14:10.001294 | controller | skipping: Conditional result was False
2025-10-05 00:14:10.008289 | 
2025-10-05 00:14:10.008397 | TASK [bindep : Look for bindep fallback file]
2025-10-05 00:14:10.043035 | controller | skipping: Conditional result was False
2025-10-05 00:14:10.049115 | 
2025-10-05 00:14:10.049229 | TASK [bindep : Define bindep_file fact]
2025-10-05 00:14:10.093888 | controller | skipping: Conditional result was False
2025-10-05 00:14:10.100868 | 
2025-10-05 00:14:10.100985 | TASK [bindep : Include bindep tasks]
2025-10-05 00:14:10.135583 | controller | skipping: Conditional result was False
2025-10-05 00:14:10.143389 | 
2025-10-05 00:14:10.143466 | TASK [bindep : Include install tasks]
2025-10-05 00:14:10.168387 | controller | skipping: Conditional result was False
2025-10-05 00:14:10.175058 | 
2025-10-05 00:14:10.175130 | LOOP [bindep : Include package tasks]
2025-10-05 00:14:10.229599 | 
2025-10-05 00:14:10.229819 | TASK [Run test-setup role]
2025-10-05 00:14:10.250321 | controller | ok
2025-10-05 00:14:10.270382 | 
2025-10-05 00:14:10.270506 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-05 00:14:10.582192 | controller | ok
2025-10-05 00:14:10.596676 | 
2025-10-05 00:14:10.596854 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-05 00:14:10.739816 | controller | skipping: Conditional result was False
2025-10-05 00:14:10.795790 | 
2025-10-05 00:14:10.795986 | PLAY RECAP
2025-10-05 00:14:10.796102 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-05 00:14:10.796165 | 
2025-10-05 00:14:10.927240 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-05 00:14:10.929074 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-05 00:14:11.479228 | 
2025-10-05 00:14:11.479352 | PLAY [controller]
2025-10-05 00:14:11.498369 | 
2025-10-05 00:14:11.498485 | TASK [Create the /root directory]
2025-10-05 00:14:12.270135 | controller | ok
2025-10-05 00:14:12.276168 | 
2025-10-05 00:14:12.276253 | TASK [Install glibc-langpack-en]
2025-10-05 00:14:20.482902 | controller | ok: Nothing to do
2025-10-05 00:14:20.490803 | 
2025-10-05 00:14:20.490892 | TASK [Ensure controller directory exists]
2025-10-05 00:14:20.977476 | controller | changed
2025-10-05 00:14:20.990163 | 
2025-10-05 00:14:20.990313 | TASK [Install container runtime]
2025-10-05 00:14:21.055808 | controller | ok
2025-10-05 00:14:21.101445 | 
2025-10-05 00:14:21.101586 | LOOP [ensure-podman : Find distribution installation]
2025-10-05 00:14:21.133540 | controller | ok: "/var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-05 00:14:21.144696 | controller | included: /var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-05 00:14:21.153514 | 
2025-10-05 00:14:21.153634 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-05 00:15:42.707402 | controller | changed
2025-10-05 00:15:42.716224 | 
2025-10-05 00:15:42.716321 | TASK [ensure-podman : Fetch podman version]
2025-10-05 00:15:43.408800 | controller | Client:       Podman Engine
2025-10-05 00:15:43.408891 | controller | Version:      4.6.2
2025-10-05 00:15:43.408922 | controller | API Version:  4.6.2
2025-10-05 00:15:43.408949 | controller | Go Version:   go1.19.12
2025-10-05 00:15:43.408985 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-05 00:15:43.409012 | controller | OS/Arch:      linux/amd64
2025-10-05 00:15:43.856611 | controller | ok: Runtime: 0:00:00.222802
2025-10-05 00:15:43.865069 | 
2025-10-05 00:15:43.865186 | TASK [ensure-podman : Print podman version installed]
2025-10-05 00:15:43.896966 | Podman version: Client:       Podman Engine
2025-10-05 00:15:43.897128 | Version:      4.6.2
2025-10-05 00:15:43.897158 | API Version:  4.6.2
2025-10-05 00:15:43.897180 | Go Version:   go1.19.12
2025-10-05 00:15:43.897199 | Built:        Mon Aug 28 19:38:31 2023
2025-10-05 00:15:43.897218 | OS/Arch:      linux/amd64
2025-10-05 00:15:43.902833 | 
2025-10-05 00:15:43.902897 | TASK [ensure-podman : Validate podman engine]
2025-10-05 00:15:44.027334 | controller | skipping: Conditional result was False
2025-10-05 00:15:44.033963 | 
2025-10-05 00:15:44.034063 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-05 00:15:44.058436 | controller | skipping: Conditional result was False
2025-10-05 00:15:44.068995 | 
2025-10-05 00:15:44.069117 | TASK [Ensure python3.8 is present]
2025-10-05 00:15:44.093594 | controller | skipping: Conditional result was False
2025-10-05 00:15:44.099521 | 
2025-10-05 00:15:44.099610 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-05 00:15:44.119883 | controller | ok
2025-10-05 00:15:44.139837 | 
2025-10-05 00:15:44.139949 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-05 00:15:47.782106 | controller | ok: Nothing to do
2025-10-05 00:15:47.790056 | 
2025-10-05 00:15:47.790215 | TASK [our-ensure-python : Also install python3-devel]
2025-10-05 00:16:01.227896 | controller | changed
2025-10-05 00:16:01.243450 | 
2025-10-05 00:16:01.243594 | TASK [Run ensure-virtualenv role]
2025-10-05 00:16:01.268629 | controller | ok
2025-10-05 00:16:01.301617 | 
2025-10-05 00:16:01.301768 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-05 00:16:02.412303 | controller | /usr/bin/virtualenv
2025-10-05 00:16:02.939543 | controller | ok: Runtime: 0:00:00.014313
2025-10-05 00:16:02.947522 | 
2025-10-05 00:16:02.947657 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-05 00:16:02.973698 | controller | skipping: Conditional result was False
2025-10-05 00:16:02.973961 | controller | ok: All items complete
2025-10-05 00:16:02.973990 | 
2025-10-05 00:16:02.988802 | 
2025-10-05 00:16:02.988933 | TASK [Find the full path of the Python interpreter]
2025-10-05 00:16:03.502971 | controller | /usr/bin/python3
2025-10-05 00:16:03.656047 | controller | ok
2025-10-05 00:16:03.662368 | 
2025-10-05 00:16:03.662475 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-05 00:16:05.063510 | controller | created virtual environment CPython3.11.0.final.0-64 in 774ms
2025-10-05 00:16:05.118744 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-05 00:16:05.121226 | 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-05 00:16:05.121265 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-05 00:16:05.121292 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-05 00:16:05.301735 | controller | changed
2025-10-05 00:16:05.307868 | 
2025-10-05 00:16:05.307949 | TASK [Set selinux package]
2025-10-05 00:16:05.338954 | controller | ok
2025-10-05 00:16:05.345603 | 
2025-10-05 00:16:05.345703 | TASK [Set selinux package (Fedora)]
2025-10-05 00:16:05.393281 | controller | ok
2025-10-05 00:16:05.401851 | 
2025-10-05 00:16:05.401985 | TASK [Install selinux into virtualenv]
2025-10-05 00:16:08.055510 | controller | Collecting selinux-please-lie-to-me
2025-10-05 00:16:08.145800 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-05 00:16:08.675908 | controller | Collecting setuptools<50.0.0
2025-10-05 00:16:08.690023 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-05 00:16:08.812406 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.0 MB/s eta 0:00:00
2025-10-05 00:16:08.967130 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-05 00:16:08.967600 | controller |   Attempting uninstall: setuptools
2025-10-05 00:16:08.972641 | controller |     Found existing installation: setuptools 62.6.0
2025-10-05 00:16:09.083723 | controller |     Uninstalling setuptools-62.6.0:
2025-10-05 00:16:09.099161 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-05 00:16:09.845706 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-05 00:16:10.052667 | controller |
2025-10-05 00:16:10.269855 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-05 00:16:10.269908 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-05 00:16:10.549875 | controller | ok: Runtime: 0:00:04.383543
2025-10-05 00:16:10.558190 | 
2025-10-05 00:16:10.558327 | TASK [Install pytest-forked into virtualenv]
2025-10-05 00:16:11.754776 | controller | Collecting pytest-forked
2025-10-05 00:16:11.846594 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-05 00:16:11.905318 | controller | Collecting py
2025-10-05 00:16:11.920301 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-05 00:16:11.957583 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00
2025-10-05 00:16:12.136227 | controller | Collecting pytest>=3.10
2025-10-05 00:16:12.150989 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-05 00:16:12.248065 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 3.9 MB/s eta 0:00:00
2025-10-05 00:16:12.342035 | controller | Collecting iniconfig>=1
2025-10-05 00:16:12.356779 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-10-05 00:16:12.423180 | controller | Collecting packaging>=20
2025-10-05 00:16:12.437868 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-05 00:16:12.458457 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 3.2 MB/s eta 0:00:00
2025-10-05 00:16:12.504600 | controller | Collecting pluggy<2,>=1.5
2025-10-05 00:16:12.519029 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-05 00:16:12.591795 | controller | Collecting pygments>=2.7.2
2025-10-05 00:16:12.606984 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-05 00:16:12.856119 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 4.9 MB/s eta 0:00:00
2025-10-05 00:16:12.992975 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-05 00:16:15.232738 | 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-05 00:16:15.248973 | controller |
2025-10-05 00:16:15.437894 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-10-05 00:16:15.437947 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-05 00:16:15.718876 | controller | ok: Runtime: 0:00:04.415087
2025-10-05 00:16:15.731513 | 
2025-10-05 00:16:15.731700 | TASK [Update pip]
2025-10-05 00:16:17.058879 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-05 00:16:17.342352 | controller | Collecting pip
2025-10-05 00:16:17.447609 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-10-05 00:16:17.539157 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 20.7 MB/s eta 0:00:00
2025-10-05 00:16:17.666874 | controller | Installing collected packages: pip
2025-10-05 00:16:17.667325 | controller |   Attempting uninstall: pip
2025-10-05 00:16:17.671904 | controller |     Found existing installation: pip 22.2.2
2025-10-05 00:16:17.933658 | controller |     Uninstalling pip-22.2.2:
2025-10-05 00:16:17.963637 | controller |       Successfully uninstalled pip-22.2.2
2025-10-05 00:16:19.793895 | controller | Successfully installed pip-25.2
2025-10-05 00:16:20.390346 | controller | ok: Runtime: 0:00:03.675564
2025-10-05 00:16:20.402929 | 
2025-10-05 00:16:20.403118 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-05 00:16:20.960354 | controller | changed
2025-10-05 00:16:20.966433 | 
2025-10-05 00:16:20.966556 | TASK [Install ansible into virtualenv]
2025-10-05 00:16:22.017469 | controller | Processing ./src/github.com/ansible/ansible
2025-10-05 00:16:22.023982 | controller |   Installing build dependencies: started
2025-10-05 00:16:23.979602 | controller |   Installing build dependencies: finished with status 'done'
2025-10-05 00:16:23.980784 | controller |   Getting requirements to build wheel: started
2025-10-05 00:16:25.517264 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-05 00:16:25.518671 | controller |   Preparing metadata (pyproject.toml): started
2025-10-05 00:16:26.460241 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-05 00:16:26.463890 | 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-05 00:16:26.468823 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-05 00:16:27.132506 | controller | ERROR
2025-10-05 00:16:27.132859 | controller | {
2025-10-05 00:16:27.132938 | controller |   "delta": "0:00:05.239833",
2025-10-05 00:16:27.132987 | controller |   "end": "2025-10-05 00:16:26.621287",
2025-10-05 00:16:27.133028 | controller |   "msg": "non-zero return code",
2025-10-05 00:16:27.133082 | controller |   "rc": 1,
2025-10-05 00:16:27.133122 | controller |   "start": "2025-10-05 00:16:21.381454"
2025-10-05 00:16:27.133159 | controller | }
failure
2025-10-05 00:16:27.136139 | 
2025-10-05 00:16:27.136245 | PLAY RECAP
2025-10-05 00:16:27.136337 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-05 00:16:27.136386 | 
2025-10-05 00:16:27.276644 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-05 00:16:27.277681 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-05 00:16:27.849845 | 
2025-10-05 00:16:27.849970 | PLAY [all]
2025-10-05 00:16:27.871482 | 
2025-10-05 00:16:27.871611 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-05 00:16:28.692421 | controller | changed: non-zero return code
2025-10-05 00:16:28.704277 | 
2025-10-05 00:16:28.704436 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-05 00:16:28.731448 | controller | skipping: Conditional result was False
2025-10-05 00:16:28.744132 | 
2025-10-05 00:16:28.744277 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-05 00:16:28.784686 | 
2025-10-05 00:16:28.784996 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-05 00:16:28.824592 | 
2025-10-05 00:16:28.824922 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-05 00:16:28.852121 | controller | skipping: Conditional result was False
2025-10-05 00:16:28.858359 | 
2025-10-05 00:16:28.858430 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-05 00:16:28.889816 | 
2025-10-05 00:16:28.889968 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-05 00:16:28.914056 | controller | skipping: Conditional result was False
2025-10-05 00:16:28.919986 | 
2025-10-05 00:16:28.920068 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-05 00:16:28.934458 | controller | skipping: Conditional result was False
2025-10-05 00:16:28.940950 | 
2025-10-05 00:16:28.941013 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-05 00:16:28.964788 | controller | skipping: Conditional result was False
2025-10-05 00:16:28.989221 | 
2025-10-05 00:16:28.989297 | PLAY RECAP
2025-10-05 00:16:28.989346 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-05 00:16:28.989371 | 
2025-10-05 00:16:29.086326 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-05 00:16:29.087207 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-05 00:16:29.759423 | 
2025-10-05 00:16:29.759551 | PLAY [all:!appliance*]
2025-10-05 00:16:29.784552 | 
2025-10-05 00:16:29.784684 | TASK [unregister the node]
2025-10-05 00:16:29.920151 | controller | skipping: Conditional result was False
2025-10-05 00:16:29.928938 | 
2025-10-05 00:16:29.929067 | TASK [include_role : fetch-output]
2025-10-05 00:16:29.972445 | controller | ok
2025-10-05 00:16:30.001241 | 
2025-10-05 00:16:30.001374 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-05 00:16:30.067847 | controller | skipping: Conditional result was False
2025-10-05 00:16:30.076793 | 
2025-10-05 00:16:30.076929 | TASK [fetch-output : Set log path for single node]
2025-10-05 00:16:30.124014 | controller | ok
2025-10-05 00:16:30.135561 | 
2025-10-05 00:16:30.135780 | LOOP [fetch-output : Ensure local output dirs]
2025-10-05 00:16:30.544263 | controller -> localhost | ok: "/var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/work/logs"
2025-10-05 00:16:30.767534 | controller -> localhost | changed: "/var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/work/artifacts"
2025-10-05 00:16:31.000922 | controller -> localhost | changed: "/var/lib/zuul/builds/a663376e1fcb48a89b4792135e2b2e40/work/docs"
2025-10-05 00:16:31.017441 | 
2025-10-05 00:16:31.017568 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-05 00:16:32.269464 | controller | changed:
2025-10-05 00:16:32.269858 | controller | .d..t...... ./
2025-10-05 00:16:32.269904 | controller | cd+++++++++ controller/
2025-10-05 00:16:32.269951 | controller | changed: All items complete
2025-10-05 00:16:32.269980 | 
2025-10-05 00:16:33.276712 | controller | changed: .d..t...... ./
2025-10-05 00:16:34.398678 | controller | changed: .d..t...... ./
2025-10-05 00:16:34.429950 | 
2025-10-05 00:16:34.430190 | TASK [include_role : fetch-output-openshift]
2025-10-05 00:16:34.457211 | controller | skipping: Conditional result was False
2025-10-05 00:16:34.468672 | 
2025-10-05 00:16:34.468908 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-05 00:16:34.510355 | controller | skipping: Conditional result was False
2025-10-05 00:16:34.518528 | controller | skipping: Conditional result was False
2025-10-05 00:16:34.576493 | 
2025-10-05 00:16:34.576661 | PLAY [localhost]
2025-10-05 00:16:34.589550 | 
2025-10-05 00:16:34.589688 | TASK [Run Zuul manifest role]
2025-10-05 00:16:34.608616 | localhost | ok
2025-10-05 00:16:34.622126 | 
2025-10-05 00:16:34.622199 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-05 00:16:35.081695 | localhost | changed
2025-10-05 00:16:35.087228 | 
2025-10-05 00:16:35.087296 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-05 00:16:35.136494 | localhost | ok
2025-10-05 00:16:35.145298 | 
2025-10-05 00:16:35.145384 | TASK [Set zuul-log-path fact]
2025-10-05 00:16:35.166413 | localhost | ok
2025-10-05 00:16:35.187453 | 
2025-10-05 00:16:35.187595 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-05 00:16:35.234569 | localhost | ok
2025-10-05 00:16:35.248334 | 
2025-10-05 00:16:35.248436 | LOOP [Run upload-logs-swift role]
2025-10-05 00:16:35.296717 | localhost | Output suppressed because no_log was given
2025-10-05 00:16:35.333076 | 
2025-10-05 00:16:35.333212 | TASK [Set zuul-log-path fact]
2025-10-05 00:16:35.368619 | localhost | skipping: Conditional result was False
2025-10-05 00:16:35.376623 | 
2025-10-05 00:16:35.376798 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-05 00:16:35.829785 | localhost -> localhost | ok: Runtime: 0:00:00.009011
2025-10-05 00:16:35.835084 | 
2025-10-05 00:16:35.835151 | TASK [upload-logs-swift : Upload logs to swift]