2025-11-10 00:06:59.424005 | Job console starting...
2025-11-10 00:06:59.432589 | Updating repositories
2025-11-10 00:06:59.555949 | Preparing job workspace
2025-11-10 00:07:03.495748 | Running Ansible setup...
2025-11-10 00:07:11.237265 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-10 00:07:11.853509 | 
2025-11-10 00:07:11.853644 | PLAY [localhost]
2025-11-10 00:07:11.862757 | 
2025-11-10 00:07:11.862840 | TASK [Gathering Facts]
2025-11-10 00:07:12.953040 | localhost | ok
2025-11-10 00:07:12.984517 | 
2025-11-10 00:07:12.984716 | TASK [Setup log path fact]
2025-11-10 00:07:13.005387 | localhost | ok
2025-11-10 00:07:13.023335 | 
2025-11-10 00:07:13.023477 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-10 00:07:13.065961 | localhost | ok
2025-11-10 00:07:13.088456 | 
2025-11-10 00:07:13.088634 | TASK [emit-job-header : Print job information]
2025-11-10 00:07:13.131217 | # Job Information
2025-11-10 00:07:13.131403 | Ansible Version: 2.15.12
2025-11-10 00:07:13.131444 | Job: ansible-test-sanity-docker-devel
2025-11-10 00:07:13.131473 | Pipeline: periodic
2025-11-10 00:07:13.131498 | Executor: ze04.softwarefactory-project.io
2025-11-10 00:07:13.131523 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-10 00:07:13.131552 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/d74/ansible/d748fbfc4fa044c4b21f93577734cdad/
2025-11-10 00:07:13.131578 | Event ID: e7ed9acfd5d246fc9eb02e45c4dd8a00
2025-11-10 00:07:13.137984 | 
2025-11-10 00:07:13.138079 | LOOP [emit-job-header : Print node information]
2025-11-10 00:07:13.261364 | localhost | ok:
2025-11-10 00:07:13.261522 | localhost | # Node Information
2025-11-10 00:07:13.261549 | localhost | Inventory Hostname: controller
2025-11-10 00:07:13.261569 | localhost | Hostname: np0005516248
2025-11-10 00:07:13.261588 | localhost | Username: zuul
2025-11-10 00:07:13.261610 | localhost | Distro: Fedora 37
2025-11-10 00:07:13.261628 | localhost | Provider: ansible-vexxhost-ams1
2025-11-10 00:07:13.261646 | localhost | Region: ams1
2025-11-10 00:07:13.261663 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-10 00:07:13.261700 | localhost | Product Name: OpenStack Nova
2025-11-10 00:07:13.261736 | localhost | Interface IP: 38.129.16.135
2025-11-10 00:07:13.274636 | 
2025-11-10 00:07:13.274794 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-10 00:07:13.680565 | localhost -> localhost | changed
2025-11-10 00:07:13.694460 | 
2025-11-10 00:07:13.694620 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-10 00:07:14.560177 | localhost -> localhost | changed
2025-11-10 00:07:14.603841 | 
2025-11-10 00:07:14.603961 | PLAY [all:!appliance*]
2025-11-10 00:07:14.628068 | 
2025-11-10 00:07:14.628188 | TASK [include_role : start-zuul-console]
2025-11-10 00:07:14.653021 | controller | ok
2025-11-10 00:07:14.673434 | 
2025-11-10 00:07:14.673524 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-10 00:07:15.769474 | controller | ok
2025-11-10 00:07:15.798958 | 
2025-11-10 00:07:15.799107 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-10 00:07:17.899943 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-10 00:07:17.906937 | 
2025-11-10 00:07:17.907015 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-10 00:07:18.265447 | controller | skipping: Conditional result was False
2025-11-10 00:07:18.278780 | 
2025-11-10 00:07:18.278922 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-10 00:07:18.305473 | controller | skipping: Conditional result was False
2025-11-10 00:07:18.319877 | 
2025-11-10 00:07:18.320052 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-10 00:07:18.357307 | controller | skipping: Conditional result was False
2025-11-10 00:07:18.370570 | 
2025-11-10 00:07:18.370743 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-10 00:07:18.407536 | controller | skipping: Conditional result was False
2025-11-10 00:07:18.421916 | 
2025-11-10 00:07:18.422091 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-10 00:07:18.459768 | controller | skipping: Conditional result was False
2025-11-10 00:07:18.476659 | 
2025-11-10 00:07:18.476865 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-10 00:07:18.503437 | controller | skipping: Conditional result was False
2025-11-10 00:07:18.519913 | 
2025-11-10 00:07:18.520015 | TASK [Disable Fedora Modular]
2025-11-10 00:07:19.647072 | controller | changed
2025-11-10 00:07:19.662039 | 
2025-11-10 00:07:19.662180 | TASK [Enable EPEL]
2025-11-10 00:07:19.685070 | controller | skipping: Conditional result was False
2025-11-10 00:07:19.704246 | 
2025-11-10 00:07:19.704378 | TASK [Register the RHEL node]
2025-11-10 00:07:20.130181 | 
2025-11-10 00:07:20.130341 | TASK [Show the subscription-manager status]
2025-11-10 00:07:20.509591 | controller | skipping: Conditional result was False
2025-11-10 00:07:20.526460 | 
2025-11-10 00:07:20.526647 | TASK [Enable EPEL on RHEL]
2025-11-10 00:07:20.929671 | controller | skipping: Conditional result was False
2025-11-10 00:07:20.946403 | 
2025-11-10 00:07:20.946563 | TASK [Install git and tox]
2025-11-10 00:09:34.692753 | controller | changed
2025-11-10 00:09:34.706855 | 
2025-11-10 00:09:34.706993 | TASK [include_role : prepare-workspace]
2025-11-10 00:09:34.751415 | controller | ok
2025-11-10 00:09:34.782182 | 
2025-11-10 00:09:34.782341 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-10 00:09:35.631243 | controller | ok
2025-11-10 00:09:35.640967 | 
2025-11-10 00:09:35.641616 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-10 00:09:55.531236 | controller | Output suppressed because no_log was given
2025-11-10 00:09:55.552972 | 
2025-11-10 00:09:55.553121 | TASK [include_role : prepare-workspace-openshift]
2025-11-10 00:09:55.572270 | controller | skipping: Conditional result was False
2025-11-10 00:09:55.607170 | 
2025-11-10 00:09:55.607254 | PLAY [all:!appliance]
2025-11-10 00:09:55.623285 | 
2025-11-10 00:09:55.623388 | TASK [Run add-build-sshkey role (RSA)]
2025-11-10 00:09:55.647805 | controller | ok
2025-11-10 00:09:55.664289 | 
2025-11-10 00:09:55.664395 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-10 00:09:55.883717 | controller -> localhost | ok
2025-11-10 00:09:55.899317 | 
2025-11-10 00:09:55.899463 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-10 00:09:55.929913 | controller | ok
2025-11-10 00:09:55.959034 | controller | included: /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-10 00:09:55.968269 | 
2025-11-10 00:09:55.968367 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-10 00:09:56.499863 | controller -> localhost | Generating public/private rsa key pair.
2025-11-10 00:09:56.500100 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/work/d748fbfc4fa044c4b21f93577734cdad_id_rsa.
2025-11-10 00:09:56.500131 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/work/d748fbfc4fa044c4b21f93577734cdad_id_rsa.pub.
2025-11-10 00:09:56.500151 | controller -> localhost | The key fingerprint is:
2025-11-10 00:09:56.500170 | controller -> localhost | SHA256:0pX7kdJTiNNmBY8foVon++2xRLC6gAMHbKc+RBWsEIo zuul-build-sshkey
2025-11-10 00:09:56.500189 | controller -> localhost | The key's randomart image is:
2025-11-10 00:09:56.500207 | controller -> localhost | +---[RSA 2048]----+
2025-11-10 00:09:56.500224 | controller -> localhost | |   .. .o.   ..o  |
2025-11-10 00:09:56.500243 | controller -> localhost | |. ... ..   + * . |
2025-11-10 00:09:56.500260 | controller -> localhost | |E.  .=..  = X.=  |
2025-11-10 00:09:56.500277 | controller -> localhost | |    o.+. . O Bo. |
2025-11-10 00:09:56.500294 | controller -> localhost | |     +..S + *... |
2025-11-10 00:09:56.500322 | controller -> localhost | |    o o..  o.+.. |
2025-11-10 00:09:56.500346 | controller -> localhost | |     o o . .. .o.|
2025-11-10 00:09:56.500368 | controller -> localhost | |      . . . . ..o|
2025-11-10 00:09:56.500388 | controller -> localhost | |           .   ..|
2025-11-10 00:09:56.500408 | controller -> localhost | +----[SHA256]-----+
2025-11-10 00:09:56.500459 | controller -> localhost | ok: Runtime: 0:00:00.175153
2025-11-10 00:09:56.507672 | 
2025-11-10 00:09:56.507769 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-10 00:09:56.538364 | controller | ok
2025-11-10 00:09:56.549155 | controller | included: /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-10 00:09:56.561694 | 
2025-11-10 00:09:56.561811 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-10 00:09:56.576848 | controller | skipping: Conditional result was False
2025-11-10 00:09:56.584354 | 
2025-11-10 00:09:56.584418 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-10 00:09:57.671152 | controller | changed
2025-11-10 00:09:57.697316 | 
2025-11-10 00:09:57.697572 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-10 00:09:58.440847 | controller | ok
2025-11-10 00:09:58.457673 | 
2025-11-10 00:09:58.457884 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-10 00:10:01.572092 | controller | changed
2025-11-10 00:10:01.585598 | 
2025-11-10 00:10:01.585777 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-10 00:10:04.772977 | controller | changed
2025-11-10 00:10:04.786596 | 
2025-11-10 00:10:04.786784 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-10 00:10:04.815057 | controller | skipping: Conditional result was False
2025-11-10 00:10:04.823758 | 
2025-11-10 00:10:04.824047 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-10 00:10:05.309612 | controller -> localhost | changed
2025-11-10 00:10:05.346055 | 
2025-11-10 00:10:05.346195 | TASK [add-build-sshkey : Add back temp key]
2025-11-10 00:10:05.719776 | controller -> localhost | Identity added: /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/work/d748fbfc4fa044c4b21f93577734cdad_id_rsa (zuul-build-sshkey)
2025-11-10 00:10:05.720099 | controller -> localhost | ok: Runtime: 0:00:00.022981
2025-11-10 00:10:05.727334 | 
2025-11-10 00:10:05.727429 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-10 00:10:06.737204 | controller | ok
2025-11-10 00:10:06.746611 | 
2025-11-10 00:10:06.746816 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-10 00:10:06.784539 | controller | skipping: Conditional result was False
2025-11-10 00:10:06.812083 | 
2025-11-10 00:10:06.812257 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-10 00:10:06.848138 | controller | ok
2025-11-10 00:10:06.873731 | 
2025-11-10 00:10:06.873875 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-10 00:10:07.227589 | controller -> localhost | ok
2025-11-10 00:10:07.237499 | 
2025-11-10 00:10:07.237580 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-10 00:10:07.268338 | controller | ok
2025-11-10 00:10:07.279973 | controller | included: /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-10 00:10:07.286235 | 
2025-11-10 00:10:07.286304 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-10 00:10:07.631799 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-10 00:10:07.632086 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/work/d748fbfc4fa044c4b21f93577734cdad_id_ecdsa.
2025-11-10 00:10:07.632129 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/work/d748fbfc4fa044c4b21f93577734cdad_id_ecdsa.pub.
2025-11-10 00:10:07.632162 | controller -> localhost | The key fingerprint is:
2025-11-10 00:10:07.632183 | controller -> localhost | SHA256:kA/u+esM36dmlJ1ZsMsgs/0l4mUb8rP16EAfzPOnEsA zuul-build-sshkey
2025-11-10 00:10:07.632201 | controller -> localhost | The key's randomart image is:
2025-11-10 00:10:07.632220 | controller -> localhost | +---[ECDSA 521]---+
2025-11-10 00:10:07.632237 | controller -> localhost | |                 |
2025-11-10 00:10:07.632255 | controller -> localhost | |       .    .    |
2025-11-10 00:10:07.632272 | controller -> localhost | |      +  .   o   |
2025-11-10 00:10:07.632289 | controller -> localhost | |     . +o E .o.  |
2025-11-10 00:10:07.632306 | controller -> localhost | |      . S= *.==  |
2025-11-10 00:10:07.632323 | controller -> localhost | |     . .. *.%..+ |
2025-11-10 00:10:07.632340 | controller -> localhost | |      +  o B.*o o|
2025-11-10 00:10:07.632356 | controller -> localhost | |       = .+ Bo +.|
2025-11-10 00:10:07.632373 | controller -> localhost | |       .*+oo.=+ .|
2025-11-10 00:10:07.632389 | controller -> localhost | +----[SHA256]-----+
2025-11-10 00:10:07.632438 | controller -> localhost | ok: Runtime: 0:00:00.013929
2025-11-10 00:10:07.640630 | 
2025-11-10 00:10:07.640724 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-10 00:10:07.684709 | controller | ok
2025-11-10 00:10:07.698068 | controller | included: /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-10 00:10:07.751510 | 
2025-11-10 00:10:07.751654 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-10 00:10:07.767743 | controller | skipping: Conditional result was False
2025-11-10 00:10:07.775079 | 
2025-11-10 00:10:07.775151 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-10 00:10:08.752788 | controller | changed
2025-11-10 00:10:08.761657 | 
2025-11-10 00:10:08.761783 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-10 00:10:09.467849 | controller | ok
2025-11-10 00:10:09.482995 | 
2025-11-10 00:10:09.483152 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-10 00:10:12.618328 | controller | changed
2025-11-10 00:10:12.634509 | 
2025-11-10 00:10:12.634769 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-10 00:10:15.752871 | controller | changed
2025-11-10 00:10:15.761176 | 
2025-11-10 00:10:15.761263 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-10 00:10:15.787073 | controller | skipping: Conditional result was False
2025-11-10 00:10:15.798742 | 
2025-11-10 00:10:15.798869 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-10 00:10:16.085301 | controller -> localhost | changed
2025-11-10 00:10:16.098146 | 
2025-11-10 00:10:16.098257 | TASK [add-build-sshkey : Add back temp key]
2025-11-10 00:10:16.378101 | controller -> localhost | Identity added: /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/work/d748fbfc4fa044c4b21f93577734cdad_id_ecdsa (zuul-build-sshkey)
2025-11-10 00:10:16.378504 | controller -> localhost | ok: Runtime: 0:00:00.012876
2025-11-10 00:10:16.392553 | 
2025-11-10 00:10:16.392721 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-10 00:10:17.120078 | controller | ok
2025-11-10 00:10:17.125729 | 
2025-11-10 00:10:17.125806 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-10 00:10:17.170654 | controller | skipping: Conditional result was False
2025-11-10 00:10:17.183441 | 
2025-11-10 00:10:17.183524 | TASK [include_role : remove-zuul-sshkey]
2025-11-10 00:10:17.208630 | controller | skipping: Conditional result was False
2025-11-10 00:10:17.217635 | 
2025-11-10 00:10:17.217791 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-10 00:10:17.958428 | controller | ok: "logs"
2025-11-10 00:10:17.959028 | controller | ok: All items complete
2025-11-10 00:10:17.959109 | 
2025-11-10 00:10:18.686054 | controller | ok: "artifacts"
2025-11-10 00:10:19.353290 | controller | ok: "docs"
2025-11-10 00:10:19.378931 | 
2025-11-10 00:10:19.379151 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-10 00:10:20.101229 | controller | changed: "logs"
2025-11-10 00:10:20.755258 | controller | changed: "artifacts"
2025-11-10 00:10:21.438546 | controller | changed: "docs"
2025-11-10 00:10:21.486773 | 
2025-11-10 00:10:21.486952 | PLAY RECAP
2025-11-10 00:10:21.487032 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-10 00:10:21.487070 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-10 00:10:21.487096 | 
2025-11-10 00:10:21.689253 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-10 00:10:21.691076 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-10 00:10:22.349491 | 
2025-11-10 00:10:22.349710 | PLAY [all]
2025-11-10 00:10:22.375371 | 
2025-11-10 00:10:22.375548 | TASK [Install binary dependencies]
2025-11-10 00:10:22.449530 | controller | ok
2025-11-10 00:10:22.492783 | 
2025-11-10 00:10:22.492997 | TASK [bindep : Include find tasks]
2025-11-10 00:10:22.526094 | controller | ok
2025-11-10 00:10:22.535265 | controller | included: /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-10 00:10:22.542184 | 
2025-11-10 00:10:22.542256 | TASK [bindep : Look for bindep.txt]
2025-11-10 00:10:23.494597 | controller | ok
2025-11-10 00:10:23.510634 | 
2025-11-10 00:10:23.510930 | TASK [bindep : Define bindep_file fact]
2025-11-10 00:10:23.541080 | controller | skipping: Conditional result was False
2025-11-10 00:10:23.556906 | 
2025-11-10 00:10:23.557146 | TASK [bindep : Look for other-requirements.txt]
2025-11-10 00:10:24.227762 | controller | ok
2025-11-10 00:10:24.244134 | 
2025-11-10 00:10:24.244449 | TASK [bindep : Define bindep_file fact]
2025-11-10 00:10:24.284583 | controller | skipping: Conditional result was False
2025-11-10 00:10:24.295555 | 
2025-11-10 00:10:24.295721 | TASK [bindep : Look for bindep fallback file]
2025-11-10 00:10:24.334598 | controller | skipping: Conditional result was False
2025-11-10 00:10:24.345200 | 
2025-11-10 00:10:24.345421 | TASK [bindep : Define bindep_file fact]
2025-11-10 00:10:24.372429 | controller | skipping: Conditional result was False
2025-11-10 00:10:24.382307 | 
2025-11-10 00:10:24.382492 | TASK [bindep : Include bindep tasks]
2025-11-10 00:10:24.409210 | controller | skipping: Conditional result was False
2025-11-10 00:10:24.419596 | 
2025-11-10 00:10:24.419893 | TASK [bindep : Include install tasks]
2025-11-10 00:10:24.454335 | controller | skipping: Conditional result was False
2025-11-10 00:10:24.464322 | 
2025-11-10 00:10:24.464453 | LOOP [bindep : Include package tasks]
2025-11-10 00:10:24.576359 | 
2025-11-10 00:10:24.576604 | TASK [Run test-setup role]
2025-11-10 00:10:24.600553 | controller | ok
2025-11-10 00:10:24.628673 | 
2025-11-10 00:10:24.628786 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-10 00:10:25.393300 | controller | ok
2025-11-10 00:10:25.408316 | 
2025-11-10 00:10:25.408490 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-10 00:10:25.782664 | controller | skipping: Conditional result was False
2025-11-10 00:10:25.837075 | 
2025-11-10 00:10:25.837307 | PLAY RECAP
2025-11-10 00:10:25.837378 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-10 00:10:25.837408 | 
2025-11-10 00:10:26.027312 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-10 00:10:26.028567 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-10 00:10:26.690561 | 
2025-11-10 00:10:26.690717 | PLAY [controller]
2025-11-10 00:10:26.711464 | 
2025-11-10 00:10:26.711554 | TASK [Create the /root directory]
2025-11-10 00:10:27.835523 | controller | ok
2025-11-10 00:10:27.852910 | 
2025-11-10 00:10:27.853121 | TASK [Install glibc-langpack-en]
2025-11-10 00:10:36.228312 | controller | ok: Nothing to do
2025-11-10 00:10:36.243427 | 
2025-11-10 00:10:36.243815 | TASK [Ensure controller directory exists]
2025-11-10 00:10:37.084554 | controller | changed
2025-11-10 00:10:37.097524 | 
2025-11-10 00:10:37.097786 | TASK [Install container runtime]
2025-11-10 00:10:37.180561 | controller | ok
2025-11-10 00:10:37.267771 | 
2025-11-10 00:10:37.267986 | LOOP [ensure-podman : Find distribution installation]
2025-11-10 00:10:37.324949 | controller | ok: "/var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-10 00:10:37.352103 | controller | included: /var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-10 00:10:37.367077 | 
2025-11-10 00:10:37.367231 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-10 00:12:40.351331 | controller | changed
2025-11-10 00:12:40.365414 | 
2025-11-10 00:12:40.365571 | TASK [ensure-podman : Fetch podman version]
2025-11-10 00:12:41.523554 | controller | Client:       Podman Engine
2025-11-10 00:12:41.558022 | controller | Version:      4.6.2
2025-11-10 00:12:41.558075 | controller | API Version:  4.6.2
2025-11-10 00:12:41.558084 | controller | Go Version:   go1.19.12
2025-11-10 00:12:41.558105 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-10 00:12:41.558113 | controller | OS/Arch:      linux/amd64
2025-11-10 00:12:41.735882 | controller | ok: Runtime: 0:00:00.291028
2025-11-10 00:12:41.751448 | 
2025-11-10 00:12:41.751636 | TASK [ensure-podman : Print podman version installed]
2025-11-10 00:12:41.795040 | Podman version: Client:       Podman Engine
2025-11-10 00:12:41.795280 | Version:      4.6.2
2025-11-10 00:12:41.795319 | API Version:  4.6.2
2025-11-10 00:12:41.795348 | Go Version:   go1.19.12
2025-11-10 00:12:41.795373 | Built:        Mon Aug 28 19:38:31 2023
2025-11-10 00:12:41.795401 | OS/Arch:      linux/amd64
2025-11-10 00:12:41.803162 | 
2025-11-10 00:12:41.803246 | TASK [ensure-podman : Validate podman engine]
2025-11-10 00:12:42.164190 | controller | skipping: Conditional result was False
2025-11-10 00:12:42.170922 | 
2025-11-10 00:12:42.170998 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-10 00:12:42.185042 | controller | skipping: Conditional result was False
2025-11-10 00:12:42.197138 | 
2025-11-10 00:12:42.197253 | TASK [Ensure python3.8 is present]
2025-11-10 00:12:42.211609 | controller | skipping: Conditional result was False
2025-11-10 00:12:42.218412 | 
2025-11-10 00:12:42.218490 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-10 00:12:42.238381 | controller | ok
2025-11-10 00:12:42.260148 | 
2025-11-10 00:12:42.260282 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-10 00:12:45.816384 | controller | ok: Nothing to do
2025-11-10 00:12:45.828508 | 
2025-11-10 00:12:45.828646 | TASK [our-ensure-python : Also install python3-devel]
2025-11-10 00:13:01.046851 | controller | changed
2025-11-10 00:13:01.071616 | 
2025-11-10 00:13:01.071784 | TASK [Run ensure-virtualenv role]
2025-11-10 00:13:01.100085 | controller | ok
2025-11-10 00:13:01.131913 | 
2025-11-10 00:13:01.132062 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-10 00:13:01.988078 | controller | /usr/bin/virtualenv
2025-11-10 00:13:02.530152 | controller | ok: Runtime: 0:00:00.006838
2025-11-10 00:13:02.544280 | 
2025-11-10 00:13:02.544444 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-10 00:13:02.582611 | controller | skipping: Conditional result was False
2025-11-10 00:13:02.583182 | controller | ok: All items complete
2025-11-10 00:13:02.583222 | 
2025-11-10 00:13:02.620425 | 
2025-11-10 00:13:02.620638 | TASK [Find the full path of the Python interpreter]
2025-11-10 00:13:03.411284 | controller | /usr/bin/python3
2025-11-10 00:13:03.996402 | controller | ok
2025-11-10 00:13:04.019740 | 
2025-11-10 00:13:04.019909 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-10 00:13:05.857388 | controller | created virtual environment CPython3.11.0.final.0-64 in 872ms
2025-11-10 00:13:05.919703 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-10 00:13:05.919756 | 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/.local/share/virtualenv)
2025-11-10 00:13:05.919771 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-10 00:13:05.919790 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-10 00:13:06.409393 | controller | changed
2025-11-10 00:13:06.423328 | 
2025-11-10 00:13:06.423492 | TASK [Set selinux package]
2025-11-10 00:13:06.455091 | controller | ok
2025-11-10 00:13:06.463109 | 
2025-11-10 00:13:06.463229 | TASK [Set selinux package (Fedora)]
2025-11-10 00:13:06.509821 | controller | ok
2025-11-10 00:13:06.519238 | 
2025-11-10 00:13:06.519340 | TASK [Install selinux into virtualenv]
2025-11-10 00:13:09.576073 | controller | Collecting selinux-please-lie-to-me
2025-11-10 00:13:09.639093 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-10 00:13:10.216802 | controller | Collecting setuptools<50.0.0
2025-11-10 00:13:10.322358 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-10 00:13:10.374266 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 17.7 MB/s eta 0:00:00
2025-11-10 00:13:10.527001 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-10 00:13:10.527366 | controller |   Attempting uninstall: setuptools
2025-11-10 00:13:10.532896 | controller |     Found existing installation: setuptools 62.6.0
2025-11-10 00:13:10.652369 | controller |     Uninstalling setuptools-62.6.0:
2025-11-10 00:13:10.667944 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-10 00:13:11.634755 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-10 00:13:11.840996 | controller |
2025-11-10 00:13:12.147508 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-10 00:13:12.147557 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-10 00:13:12.402775 | controller | ok: Runtime: 0:00:04.837839
2025-11-10 00:13:12.417220 | 
2025-11-10 00:13:12.417411 | TASK [Install pytest-forked into virtualenv]
2025-11-10 00:13:13.900050 | controller | Collecting pytest-forked
2025-11-10 00:13:13.962467 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-10 00:13:14.030815 | controller | Collecting py
2025-11-10 00:13:14.036509 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-10 00:13:14.069304 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.3 MB/s eta 0:00:00
2025-11-10 00:13:14.280384 | controller | Collecting pytest>=3.10
2025-11-10 00:13:14.288648 | controller |   Downloading pytest-9.0.0-py3-none-any.whl (373 kB)
2025-11-10 00:13:14.316196 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.4/373.4 kB 21.6 MB/s eta 0:00:00
2025-11-10 00:13:14.372884 | controller | Collecting iniconfig>=1.0.1
2025-11-10 00:13:14.377111 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-10 00:13:14.455587 | controller | Collecting packaging>=22
2025-11-10 00:13:14.461835 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-10 00:13:14.481234 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.2 MB/s eta 0:00:00
2025-11-10 00:13:14.524849 | controller | Collecting pluggy<2,>=1.5
2025-11-10 00:13:14.529998 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-10 00:13:14.616083 | controller | Collecting pygments>=2.7.2
2025-11-10 00:13:14.623705 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-10 00:13:14.665380 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 33.9 MB/s eta 0:00:00
2025-11-10 00:13:14.783763 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-10 00:13:17.404654 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.0 pytest-forked-1.6.0
2025-11-10 00:13:17.422540 | controller |
2025-11-10 00:13:17.735134 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-10 00:13:17.735190 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-10 00:13:18.309042 | controller | ok: Runtime: 0:00:04.524492
2025-11-10 00:13:18.324936 | 
2025-11-10 00:13:18.325087 | TASK [Update pip]
2025-11-10 00:13:19.885766 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-10 00:13:20.229177 | controller | Collecting pip
2025-11-10 00:13:20.315387 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-10 00:13:20.398910 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 22.7 MB/s eta 0:00:00
2025-11-10 00:13:20.581937 | controller | Installing collected packages: pip
2025-11-10 00:13:20.584300 | controller |   Attempting uninstall: pip
2025-11-10 00:13:20.595083 | controller |     Found existing installation: pip 22.2.2
2025-11-10 00:13:20.863557 | controller |     Uninstalling pip-22.2.2:
2025-11-10 00:13:20.892609 | controller |       Successfully uninstalled pip-22.2.2
2025-11-10 00:13:22.805252 | controller | Successfully installed pip-25.3
2025-11-10 00:13:23.229197 | controller | ok: Runtime: 0:00:03.889585
2025-11-10 00:13:23.238744 | 
2025-11-10 00:13:23.238863 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-10 00:13:24.099128 | controller | changed
2025-11-10 00:13:24.104956 | 
2025-11-10 00:13:24.105024 | TASK [Install ansible into virtualenv]
2025-11-10 00:13:25.396166 | controller | Processing ./src/github.com/ansible/ansible
2025-11-10 00:13:25.404418 | controller |   Installing build dependencies: started
2025-11-10 00:13:27.282716 | controller |   Installing build dependencies: finished with status 'done'
2025-11-10 00:13:27.283768 | controller |   Getting requirements to build wheel: started
2025-11-10 00:13:28.931944 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-10 00:13:28.933439 | controller |   Preparing metadata (pyproject.toml): started
2025-11-10 00:13:29.886255 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-10 00:13:29.891881 | 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-11-10 00:13:29.902401 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-10 00:13:30.507067 | controller | ERROR
2025-11-10 00:13:30.507271 | controller | {
2025-11-10 00:13:30.507314 | controller |   "delta": "0:00:05.303618",
2025-11-10 00:13:30.507345 | controller |   "end": "2025-11-10 00:13:30.072896",
2025-11-10 00:13:30.507375 | controller |   "msg": "non-zero return code",
2025-11-10 00:13:30.507404 | controller |   "rc": 1,
2025-11-10 00:13:30.507422 | controller |   "start": "2025-11-10 00:13:24.769278"
2025-11-10 00:13:30.507438 | controller | }
failure
2025-11-10 00:13:30.508887 | 
2025-11-10 00:13:30.508945 | PLAY RECAP
2025-11-10 00:13:30.509002 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-10 00:13:30.509032 | 
2025-11-10 00:13:30.636994 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-10 00:13:30.637995 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-10 00:13:31.253459 | 
2025-11-10 00:13:31.253584 | PLAY [all]
2025-11-10 00:13:31.276064 | 
2025-11-10 00:13:31.276216 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-10 00:13:33.127639 | controller | changed: non-zero return code
2025-11-10 00:13:33.133826 | 
2025-11-10 00:13:33.133916 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-10 00:13:33.159551 | controller | skipping: Conditional result was False
2025-11-10 00:13:33.174164 | 
2025-11-10 00:13:33.174323 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-10 00:13:33.217320 | 
2025-11-10 00:13:33.217595 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-10 00:13:33.253507 | 
2025-11-10 00:13:33.253698 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-10 00:13:33.278628 | controller | skipping: Conditional result was False
2025-11-10 00:13:33.287087 | 
2025-11-10 00:13:33.287181 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-10 00:13:33.321191 | 
2025-11-10 00:13:33.321358 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-10 00:13:33.346336 | controller | skipping: Conditional result was False
2025-11-10 00:13:33.354748 | 
2025-11-10 00:13:33.354832 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-10 00:13:33.371947 | controller | skipping: Conditional result was False
2025-11-10 00:13:33.381403 | 
2025-11-10 00:13:33.381495 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-10 00:13:33.406934 | controller | skipping: Conditional result was False
2025-11-10 00:13:33.442841 | 
2025-11-10 00:13:33.442912 | PLAY RECAP
2025-11-10 00:13:33.442970 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-10 00:13:33.442998 | 
2025-11-10 00:13:33.544671 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-10 00:13:33.547211 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-10 00:13:34.158093 | 
2025-11-10 00:13:34.158209 | PLAY [all:!appliance*]
2025-11-10 00:13:34.180107 | 
2025-11-10 00:13:34.180211 | TASK [unregister the node]
2025-11-10 00:13:34.532572 | controller | skipping: Conditional result was False
2025-11-10 00:13:34.546529 | 
2025-11-10 00:13:34.546811 | TASK [include_role : fetch-output]
2025-11-10 00:13:34.597976 | controller | ok
2025-11-10 00:13:34.641296 | 
2025-11-10 00:13:34.641432 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-10 00:13:34.718258 | controller | skipping: Conditional result was False
2025-11-10 00:13:34.728961 | 
2025-11-10 00:13:34.729088 | TASK [fetch-output : Set log path for single node]
2025-11-10 00:13:34.776148 | controller | ok
2025-11-10 00:13:34.787971 | 
2025-11-10 00:13:34.788106 | LOOP [fetch-output : Ensure local output dirs]
2025-11-10 00:13:35.233813 | controller -> localhost | ok: "/var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/work/logs"
2025-11-10 00:13:35.481156 | controller -> localhost | changed: "/var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/work/artifacts"
2025-11-10 00:13:35.708819 | controller -> localhost | changed: "/var/lib/zuul/builds/d748fbfc4fa044c4b21f93577734cdad/work/docs"
2025-11-10 00:13:35.721854 | 
2025-11-10 00:13:35.721966 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-10 00:13:37.941635 | controller | changed:
2025-11-10 00:13:37.941983 | controller | .d..t...... ./
2025-11-10 00:13:37.942021 | controller | cd+++++++++ controller/
2025-11-10 00:13:37.942065 | controller | changed: All items complete
2025-11-10 00:13:37.942089 | 
2025-11-10 00:13:40.067314 | controller | changed: .d..t...... ./
2025-11-10 00:13:42.176982 | controller | changed: .d..t...... ./
2025-11-10 00:13:42.205033 | 
2025-11-10 00:13:42.205239 | TASK [include_role : fetch-output-openshift]
2025-11-10 00:13:42.230752 | controller | skipping: Conditional result was False
2025-11-10 00:13:42.240585 | 
2025-11-10 00:13:42.240708 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-10 00:13:42.282599 | controller | skipping: Conditional result was False
2025-11-10 00:13:42.294374 | controller | skipping: Conditional result was False
2025-11-10 00:13:42.337260 | 
2025-11-10 00:13:42.337444 | PLAY [localhost]
2025-11-10 00:13:42.356500 | 
2025-11-10 00:13:42.356604 | TASK [Run Zuul manifest role]
2025-11-10 00:13:42.388212 | localhost | ok
2025-11-10 00:13:42.407937 | 
2025-11-10 00:13:42.408030 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-10 00:13:42.824036 | localhost | changed
2025-11-10 00:13:42.828534 | 
2025-11-10 00:13:42.828595 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-10 00:13:42.857276 | localhost | ok
2025-11-10 00:13:42.866643 | 
2025-11-10 00:13:42.866744 | TASK [Set zuul-log-path fact]
2025-11-10 00:13:42.923648 | localhost | ok
2025-11-10 00:13:42.937022 | 
2025-11-10 00:13:42.937109 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-10 00:13:42.979512 | localhost | ok
2025-11-10 00:13:42.988627 | 
2025-11-10 00:13:42.988731 | LOOP [Run upload-logs-swift role]
2025-11-10 00:13:43.034161 | localhost | Output suppressed because no_log was given
2025-11-10 00:13:43.080071 | 
2025-11-10 00:13:43.080247 | TASK [Set zuul-log-path fact]
2025-11-10 00:13:43.116001 | localhost | skipping: Conditional result was False
2025-11-10 00:13:43.122461 | 
2025-11-10 00:13:43.122572 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-10 00:13:43.536461 | localhost -> localhost | ok: Runtime: 0:00:00.009646
2025-11-10 00:13:43.551111 | 
2025-11-10 00:13:43.551286 | TASK [upload-logs-swift : Upload logs to swift]