2025-09-29 00:06:36.040134 | Job console starting...
2025-09-29 00:06:36.054137 | Updating repositories
2025-09-29 00:06:36.250286 | Preparing job workspace
2025-09-29 00:06:42.264665 | Running Ansible setup...
2025-09-29 00:06:48.356151 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-29 00:06:48.938675 | 
2025-09-29 00:06:48.938807 | PLAY [localhost]
2025-09-29 00:06:48.947385 | 
2025-09-29 00:06:48.947460 | TASK [Gathering Facts]
2025-09-29 00:06:49.870274 | localhost | ok
2025-09-29 00:06:49.899458 | 
2025-09-29 00:06:49.899684 | TASK [Setup log path fact]
2025-09-29 00:06:49.920374 | localhost | ok
2025-09-29 00:06:49.940018 | 
2025-09-29 00:06:49.940165 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-29 00:06:49.970385 | localhost | ok
2025-09-29 00:06:49.981901 | 
2025-09-29 00:06:49.982035 | TASK [emit-job-header : Print job information]
2025-09-29 00:06:50.023071 | # Job Information
2025-09-29 00:06:50.023266 | Ansible Version: 2.15.12
2025-09-29 00:06:50.023313 | Job: ansible-test-sanity-docker-devel
2025-09-29 00:06:50.023345 | Pipeline: periodic
2025-09-29 00:06:50.023375 | Executor: ze03.softwarefactory-project.io
2025-09-29 00:06:50.023399 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-29 00:06:50.023566 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/d57/ansible/d5707eadc3ee48a08b1faaeae891cfec/
2025-09-29 00:06:50.023590 | Event ID: c18e3d24a25249e3bcbdaf54f0d57ff2
2025-09-29 00:06:50.028603 | 
2025-09-29 00:06:50.028699 | LOOP [emit-job-header : Print node information]
2025-09-29 00:06:50.121805 | localhost | ok:
2025-09-29 00:06:50.121997 | localhost | # Node Information
2025-09-29 00:06:50.122024 | localhost | Inventory Hostname: controller
2025-09-29 00:06:50.122054 | localhost | Hostname: ip-172-16-34-100
2025-09-29 00:06:50.122074 | localhost | Username: zuul-worker
2025-09-29 00:06:50.122093 | localhost | Distro: Fedora 37
2025-09-29 00:06:50.122111 | localhost | Provider: ansible-us-east-2
2025-09-29 00:06:50.122128 | localhost | Region: us-east-2
2025-09-29 00:06:50.122145 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-29 00:06:50.122161 | localhost | Product Name: t3.small
2025-09-29 00:06:50.122178 | localhost | Interface IP: 52.15.135.113
2025-09-29 00:06:50.137678 | 
2025-09-29 00:06:50.137864 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-29 00:06:50.526290 | localhost -> localhost | changed
2025-09-29 00:06:50.531547 | 
2025-09-29 00:06:50.531634 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-29 00:06:51.421181 | localhost -> localhost | changed
2025-09-29 00:06:51.466634 | 
2025-09-29 00:06:51.466789 | PLAY [all:!appliance*]
2025-09-29 00:06:51.483103 | 
2025-09-29 00:06:51.483206 | TASK [include_role : start-zuul-console]
2025-09-29 00:06:51.501826 | controller | ok
2025-09-29 00:06:51.515887 | 
2025-09-29 00:06:51.515982 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-29 00:06:52.195539 | controller | ok
2025-09-29 00:06:52.207549 | 
2025-09-29 00:06:52.207662 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-29 00:06:53.615862 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-29 00:06:53.628647 | 
2025-09-29 00:06:53.628854 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-29 00:06:53.777948 | controller | skipping: Conditional result was False
2025-09-29 00:06:53.791494 | 
2025-09-29 00:06:53.791631 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-29 00:06:53.824206 | controller | skipping: Conditional result was False
2025-09-29 00:06:53.837248 | 
2025-09-29 00:06:53.837434 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-29 00:06:53.865332 | controller | skipping: Conditional result was False
2025-09-29 00:06:53.893677 | 
2025-09-29 00:06:53.893906 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-29 00:06:53.931112 | controller | skipping: Conditional result was False
2025-09-29 00:06:53.943924 | 
2025-09-29 00:06:53.944094 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-29 00:06:53.970192 | controller | skipping: Conditional result was False
2025-09-29 00:06:53.978791 | 
2025-09-29 00:06:53.978898 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-29 00:06:54.003785 | controller | skipping: Conditional result was False
2025-09-29 00:06:54.023462 | 
2025-09-29 00:06:54.023619 | TASK [Disable Fedora Modular]
2025-09-29 00:06:54.763934 | controller | changed
2025-09-29 00:06:54.778356 | 
2025-09-29 00:06:54.778535 | TASK [Enable EPEL]
2025-09-29 00:06:54.805964 | controller | skipping: Conditional result was False
2025-09-29 00:06:54.820216 | 
2025-09-29 00:06:54.820417 | TASK [Register the RHEL node]
2025-09-29 00:06:54.997799 | 
2025-09-29 00:06:54.998060 | TASK [Show the subscription-manager status]
2025-09-29 00:06:55.185220 | controller | skipping: Conditional result was False
2025-09-29 00:06:55.234655 | 
2025-09-29 00:06:55.234818 | TASK [Enable EPEL on RHEL]
2025-09-29 00:06:55.389414 | controller | skipping: Conditional result was False
2025-09-29 00:06:55.395439 | 
2025-09-29 00:06:55.395507 | TASK [Install git and tox]
2025-09-29 00:08:26.266295 | controller | changed
2025-09-29 00:08:26.282154 | 
2025-09-29 00:08:26.282335 | TASK [include_role : prepare-workspace]
2025-09-29 00:08:26.309650 | controller | ok
2025-09-29 00:08:26.342702 | 
2025-09-29 00:08:26.342875 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-29 00:08:26.988159 | controller | ok
2025-09-29 00:08:26.995133 | 
2025-09-29 00:08:26.995233 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-29 00:08:41.304804 | controller | Output suppressed because no_log was given
2025-09-29 00:08:41.319614 | 
2025-09-29 00:08:41.319763 | TASK [include_role : prepare-workspace-openshift]
2025-09-29 00:08:41.345030 | controller | skipping: Conditional result was False
2025-09-29 00:08:41.370271 | 
2025-09-29 00:08:41.370365 | PLAY [all:!appliance]
2025-09-29 00:08:41.390363 | 
2025-09-29 00:08:41.390526 | TASK [Run add-build-sshkey role (RSA)]
2025-09-29 00:08:41.421657 | controller | ok
2025-09-29 00:08:41.467970 | 
2025-09-29 00:08:41.468096 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-29 00:08:41.728260 | controller -> localhost | ok
2025-09-29 00:08:41.734830 | 
2025-09-29 00:08:41.734904 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-29 00:08:41.760668 | controller | ok
2025-09-29 00:08:41.785060 | controller | included: /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-29 00:08:41.794516 | 
2025-09-29 00:08:41.794663 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-29 00:08:42.333013 | controller -> localhost | Generating public/private rsa key pair.
2025-09-29 00:08:42.333374 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/work/d5707eadc3ee48a08b1faaeae891cfec_id_rsa.
2025-09-29 00:08:42.333435 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/work/d5707eadc3ee48a08b1faaeae891cfec_id_rsa.pub.
2025-09-29 00:08:42.333482 | controller -> localhost | The key fingerprint is:
2025-09-29 00:08:42.333526 | controller -> localhost | SHA256:EEwbrdLxkeGNp6Vku8As7CpS1M7dlZOGMcPFurx6yew zuul-build-sshkey
2025-09-29 00:08:42.333569 | controller -> localhost | The key's randomart image is:
2025-09-29 00:08:42.333612 | controller -> localhost | +---[RSA 2048]----+
2025-09-29 00:08:42.333654 | controller -> localhost | |     o+o.=.      |
2025-09-29 00:08:42.333697 | controller -> localhost | |      o=Oo.      |
2025-09-29 00:08:42.333800 | controller -> localhost | |   . .o+=B+o     |
2025-09-29 00:08:42.333847 | controller -> localhost | |  ..ooo++**      |
2025-09-29 00:08:42.333910 | controller -> localhost | | . ooo+oS+ .     |
2025-09-29 00:08:42.334177 | controller -> localhost | |  ..o...+.       |
2025-09-29 00:08:42.334355 | controller -> localhost | | .  .  o.o       |
2025-09-29 00:08:42.334412 | controller -> localhost | |o  .    *        |
2025-09-29 00:08:42.334459 | controller -> localhost | |...   .+E        |
2025-09-29 00:08:42.334509 | controller -> localhost | +----[SHA256]-----+
2025-09-29 00:08:42.334622 | controller -> localhost | ok: Runtime: 0:00:00.125372
2025-09-29 00:08:42.353524 | 
2025-09-29 00:08:42.353673 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-29 00:08:42.397645 | controller | ok
2025-09-29 00:08:42.413282 | controller | included: /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-29 00:08:42.426543 | 
2025-09-29 00:08:42.426677 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-29 00:08:42.462346 | controller | skipping: Conditional result was False
2025-09-29 00:08:42.471918 | 
2025-09-29 00:08:42.472057 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-29 00:08:43.084892 | controller | changed
2025-09-29 00:08:43.099815 | 
2025-09-29 00:08:43.100152 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-29 00:08:43.486633 | controller | ok
2025-09-29 00:08:43.493766 | 
2025-09-29 00:08:43.493888 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-29 00:08:44.803597 | controller | changed
2025-09-29 00:08:44.811675 | 
2025-09-29 00:08:44.811788 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-29 00:08:46.277368 | controller | changed
2025-09-29 00:08:46.285803 | 
2025-09-29 00:08:46.285892 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-29 00:08:46.310702 | controller | skipping: Conditional result was False
2025-09-29 00:08:46.320019 | 
2025-09-29 00:08:46.320116 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-29 00:08:46.650094 | controller -> localhost | changed
2025-09-29 00:08:46.669502 | 
2025-09-29 00:08:46.669644 | TASK [add-build-sshkey : Add back temp key]
2025-09-29 00:08:46.950127 | controller -> localhost | Identity added: /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/work/d5707eadc3ee48a08b1faaeae891cfec_id_rsa (zuul-build-sshkey)
2025-09-29 00:08:46.950330 | controller -> localhost | ok: Runtime: 0:00:00.007970
2025-09-29 00:08:46.959031 | 
2025-09-29 00:08:46.959121 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-29 00:08:47.457274 | controller | ok
2025-09-29 00:08:47.471881 | 
2025-09-29 00:08:47.472090 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-29 00:08:47.501171 | controller | skipping: Conditional result was False
2025-09-29 00:08:47.529766 | 
2025-09-29 00:08:47.530139 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-29 00:08:47.554983 | controller | ok
2025-09-29 00:08:47.576360 | 
2025-09-29 00:08:47.576566 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-29 00:08:47.856619 | controller -> localhost | ok
2025-09-29 00:08:47.865872 | 
2025-09-29 00:08:47.865973 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-29 00:08:47.900644 | controller | ok
2025-09-29 00:08:47.916665 | controller | included: /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-29 00:08:47.925175 | 
2025-09-29 00:08:47.925263 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-29 00:08:48.298897 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-29 00:08:48.299151 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/work/d5707eadc3ee48a08b1faaeae891cfec_id_ecdsa.
2025-09-29 00:08:48.299194 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/work/d5707eadc3ee48a08b1faaeae891cfec_id_ecdsa.pub.
2025-09-29 00:08:48.299247 | controller -> localhost | The key fingerprint is:
2025-09-29 00:08:48.299281 | controller -> localhost | SHA256:YRTt8sT/5/2zGybyj6S995FmIBY7irjqJrs1AEzjvhI zuul-build-sshkey
2025-09-29 00:08:48.299313 | controller -> localhost | The key's randomart image is:
2025-09-29 00:08:48.299343 | controller -> localhost | +---[ECDSA 521]---+
2025-09-29 00:08:48.299372 | controller -> localhost | | o      oo       |
2025-09-29 00:08:48.299401 | controller -> localhost | |+ .    .  .      |
2025-09-29 00:08:48.299427 | controller -> localhost | |.o      oo .     |
2025-09-29 00:08:48.299452 | controller -> localhost | |o      ...+ o    |
2025-09-29 00:08:48.299479 | controller -> localhost | |Eo      S+ * .   |
2025-09-29 00:08:48.299503 | controller -> localhost | | .o   . . + + . .|
2025-09-29 00:08:48.299526 | controller -> localhost | |.. o . . . . + B |
2025-09-29 00:08:48.299548 | controller -> localhost | |..... .     * Bo=|
2025-09-29 00:08:48.299571 | controller -> localhost | | o*o..     . =+*@|
2025-09-29 00:08:48.299597 | controller -> localhost | +----[SHA256]-----+
2025-09-29 00:08:48.299665 | controller -> localhost | ok: Runtime: 0:00:00.009274
2025-09-29 00:08:48.309337 | 
2025-09-29 00:08:48.309478 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-29 00:08:48.344091 | controller | ok
2025-09-29 00:08:48.354765 | controller | included: /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-29 00:08:48.369388 | 
2025-09-29 00:08:48.369548 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-29 00:08:48.396251 | controller | skipping: Conditional result was False
2025-09-29 00:08:48.405455 | 
2025-09-29 00:08:48.405616 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-29 00:08:48.875156 | controller | changed
2025-09-29 00:08:48.890654 | 
2025-09-29 00:08:48.890913 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-29 00:08:49.252841 | controller | ok
2025-09-29 00:08:49.262256 | 
2025-09-29 00:08:49.262377 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-29 00:08:50.627121 | controller | changed
2025-09-29 00:08:50.635429 | 
2025-09-29 00:08:50.635589 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-29 00:08:51.926450 | controller | changed
2025-09-29 00:08:51.940076 | 
2025-09-29 00:08:51.940219 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-29 00:08:51.967211 | controller | skipping: Conditional result was False
2025-09-29 00:08:51.981276 | 
2025-09-29 00:08:51.981455 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-29 00:08:52.292025 | controller -> localhost | changed
2025-09-29 00:08:52.329006 | 
2025-09-29 00:08:52.329168 | TASK [add-build-sshkey : Add back temp key]
2025-09-29 00:08:52.666173 | controller -> localhost | Identity added: /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/work/d5707eadc3ee48a08b1faaeae891cfec_id_ecdsa (zuul-build-sshkey)
2025-09-29 00:08:52.666407 | controller -> localhost | ok: Runtime: 0:00:00.012691
2025-09-29 00:08:52.676253 | 
2025-09-29 00:08:52.676358 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-29 00:08:53.062525 | controller | ok
2025-09-29 00:08:53.075649 | 
2025-09-29 00:08:53.075813 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-29 00:08:53.113302 | controller | skipping: Conditional result was False
2025-09-29 00:08:53.128439 | 
2025-09-29 00:08:53.128569 | TASK [include_role : remove-zuul-sshkey]
2025-09-29 00:08:53.155567 | controller | skipping: Conditional result was False
2025-09-29 00:08:53.163892 | 
2025-09-29 00:08:53.163972 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-29 00:08:53.528644 | controller | ok: "logs"
2025-09-29 00:08:53.528968 | controller | ok: All items complete
2025-09-29 00:08:53.529008 | 
2025-09-29 00:08:53.813006 | controller | ok: "artifacts"
2025-09-29 00:08:54.097446 | controller | ok: "docs"
2025-09-29 00:08:54.111291 | 
2025-09-29 00:08:54.111465 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-29 00:08:54.433420 | controller | changed: "logs"
2025-09-29 00:08:54.729805 | controller | changed: "artifacts"
2025-09-29 00:08:55.025170 | controller | changed: "docs"
2025-09-29 00:08:55.063249 | 
2025-09-29 00:08:55.063371 | PLAY RECAP
2025-09-29 00:08:55.063431 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-29 00:08:55.063468 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-29 00:08:55.063494 | 
2025-09-29 00:08:55.172579 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-29 00:08:55.174543 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-29 00:08:55.765056 | 
2025-09-29 00:08:55.765161 | PLAY [all]
2025-09-29 00:08:55.785746 | 
2025-09-29 00:08:55.785855 | TASK [Install binary dependencies]
2025-09-29 00:08:55.868268 | controller | ok
2025-09-29 00:08:55.895773 | 
2025-09-29 00:08:55.895936 | TASK [bindep : Include find tasks]
2025-09-29 00:08:55.938662 | controller | ok
2025-09-29 00:08:55.949194 | controller | included: /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-29 00:08:55.957512 | 
2025-09-29 00:08:55.957601 | TASK [bindep : Look for bindep.txt]
2025-09-29 00:08:56.505394 | controller | ok
2025-09-29 00:08:56.519539 | 
2025-09-29 00:08:56.519717 | TASK [bindep : Define bindep_file fact]
2025-09-29 00:08:56.537855 | controller | skipping: Conditional result was False
2025-09-29 00:08:56.546300 | 
2025-09-29 00:08:56.546407 | TASK [bindep : Look for other-requirements.txt]
2025-09-29 00:08:56.840639 | controller | ok
2025-09-29 00:08:56.848974 | 
2025-09-29 00:08:56.849119 | TASK [bindep : Define bindep_file fact]
2025-09-29 00:08:56.875802 | controller | skipping: Conditional result was False
2025-09-29 00:08:56.884757 | 
2025-09-29 00:08:56.884911 | TASK [bindep : Look for bindep fallback file]
2025-09-29 00:08:56.921449 | controller | skipping: Conditional result was False
2025-09-29 00:08:56.930812 | 
2025-09-29 00:08:56.930971 | TASK [bindep : Define bindep_file fact]
2025-09-29 00:08:56.957655 | controller | skipping: Conditional result was False
2025-09-29 00:08:56.966787 | 
2025-09-29 00:08:56.966943 | TASK [bindep : Include bindep tasks]
2025-09-29 00:08:56.992917 | controller | skipping: Conditional result was False
2025-09-29 00:08:57.003917 | 
2025-09-29 00:08:57.004078 | TASK [bindep : Include install tasks]
2025-09-29 00:08:57.030191 | controller | skipping: Conditional result was False
2025-09-29 00:08:57.038629 | 
2025-09-29 00:08:57.038799 | LOOP [bindep : Include package tasks]
2025-09-29 00:08:57.108321 | 
2025-09-29 00:08:57.108789 | TASK [Run test-setup role]
2025-09-29 00:08:57.127921 | controller | ok
2025-09-29 00:08:57.146642 | 
2025-09-29 00:08:57.146787 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-29 00:08:57.459395 | controller | ok
2025-09-29 00:08:57.471700 | 
2025-09-29 00:08:57.471873 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-29 00:08:57.622825 | controller | skipping: Conditional result was False
2025-09-29 00:08:57.691983 | 
2025-09-29 00:08:57.692089 | PLAY RECAP
2025-09-29 00:08:57.692145 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-29 00:08:57.692172 | 
2025-09-29 00:08:57.797368 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-29 00:08:57.798499 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-29 00:08:58.425249 | 
2025-09-29 00:08:58.425372 | PLAY [controller]
2025-09-29 00:08:58.444584 | 
2025-09-29 00:08:58.444666 | TASK [Create the /root directory]
2025-09-29 00:08:59.190143 | controller | ok
2025-09-29 00:08:59.199231 | 
2025-09-29 00:08:59.199371 | TASK [Install glibc-langpack-en]
2025-09-29 00:09:07.634208 | controller | ok: Nothing to do
2025-09-29 00:09:07.649188 | 
2025-09-29 00:09:07.649402 | TASK [Ensure controller directory exists]
2025-09-29 00:09:08.081888 | controller | changed
2025-09-29 00:09:08.087750 | 
2025-09-29 00:09:08.087853 | TASK [Install container runtime]
2025-09-29 00:09:08.137650 | controller | ok
2025-09-29 00:09:08.199721 | 
2025-09-29 00:09:08.199952 | LOOP [ensure-podman : Find distribution installation]
2025-09-29 00:09:08.226265 | controller | ok: "/var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-29 00:09:08.243424 | controller | included: /var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-29 00:09:08.250875 | 
2025-09-29 00:09:08.250999 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-29 00:10:24.887920 | controller | changed
2025-09-29 00:10:24.901770 | 
2025-09-29 00:10:24.901929 | TASK [ensure-podman : Fetch podman version]
2025-09-29 00:10:25.637473 | controller | Client:       Podman Engine
2025-09-29 00:10:25.666176 | controller | Version:      4.6.2
2025-09-29 00:10:25.666214 | controller | API Version:  4.6.2
2025-09-29 00:10:25.666222 | controller | Go Version:   go1.19.12
2025-09-29 00:10:25.666238 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-29 00:10:25.666246 | controller | OS/Arch:      linux/amd64
2025-09-29 00:10:26.049314 | controller | ok: Runtime: 0:00:00.193573
2025-09-29 00:10:26.059105 | 
2025-09-29 00:10:26.059253 | TASK [ensure-podman : Print podman version installed]
2025-09-29 00:10:26.097792 | Podman version: Client:       Podman Engine
2025-09-29 00:10:26.098067 | Version:      4.6.2
2025-09-29 00:10:26.098146 | API Version:  4.6.2
2025-09-29 00:10:26.098216 | Go Version:   go1.19.12
2025-09-29 00:10:26.098267 | Built:        Mon Aug 28 19:38:31 2023
2025-09-29 00:10:26.098323 | OS/Arch:      linux/amd64
2025-09-29 00:10:26.112200 | 
2025-09-29 00:10:26.112350 | TASK [ensure-podman : Validate podman engine]
2025-09-29 00:10:26.256037 | controller | skipping: Conditional result was False
2025-09-29 00:10:26.264772 | 
2025-09-29 00:10:26.264882 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-29 00:10:26.280251 | controller | skipping: Conditional result was False
2025-09-29 00:10:26.296308 | 
2025-09-29 00:10:26.296458 | TASK [Ensure python3.8 is present]
2025-09-29 00:10:26.312371 | controller | skipping: Conditional result was False
2025-09-29 00:10:26.319273 | 
2025-09-29 00:10:26.319375 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-29 00:10:26.338137 | controller | ok
2025-09-29 00:10:26.357054 | 
2025-09-29 00:10:26.357165 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-29 00:10:30.206514 | controller | ok: Nothing to do
2025-09-29 00:10:30.221337 | 
2025-09-29 00:10:30.221534 | TASK [our-ensure-python : Also install python3-devel]
2025-09-29 00:10:43.013388 | controller | changed
2025-09-29 00:10:43.033102 | 
2025-09-29 00:10:43.033305 | TASK [Run ensure-virtualenv role]
2025-09-29 00:10:43.058388 | controller | ok
2025-09-29 00:10:43.085287 | 
2025-09-29 00:10:43.085381 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-29 00:10:43.451915 | controller | /usr/bin/virtualenv
2025-09-29 00:10:43.720378 | controller | ok: Runtime: 0:00:00.004469
2025-09-29 00:10:43.729043 | 
2025-09-29 00:10:43.729148 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-29 00:10:43.750535 | controller | skipping: Conditional result was False
2025-09-29 00:10:43.751048 | controller | ok: All items complete
2025-09-29 00:10:43.751108 | 
2025-09-29 00:10:43.770769 | 
2025-09-29 00:10:43.771034 | TASK [Find the full path of the Python interpreter]
2025-09-29 00:10:44.205637 | controller | /usr/bin/python3
2025-09-29 00:10:44.403233 | controller | ok
2025-09-29 00:10:44.412944 | 
2025-09-29 00:10:44.413056 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-29 00:10:45.883737 | controller | created virtual environment CPython3.11.0.final.0-64 in 792ms
2025-09-29 00:10:45.931125 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-29 00:10:45.931176 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv)
2025-09-29 00:10:45.931194 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-29 00:10:45.931216 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-29 00:10:46.065465 | controller | changed
2025-09-29 00:10:46.073752 | 
2025-09-29 00:10:46.073876 | TASK [Set selinux package]
2025-09-29 00:10:46.097624 | controller | ok
2025-09-29 00:10:46.104934 | 
2025-09-29 00:10:46.105062 | TASK [Set selinux package (Fedora)]
2025-09-29 00:10:46.138001 | controller | ok
2025-09-29 00:10:46.145169 | 
2025-09-29 00:10:46.145277 | TASK [Install selinux into virtualenv]
2025-09-29 00:10:48.719126 | controller | Collecting selinux-please-lie-to-me
2025-09-29 00:10:48.805913 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-29 00:10:49.330013 | controller | Collecting setuptools<50.0.0
2025-09-29 00:10:49.349980 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-29 00:10:49.472950 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00
2025-09-29 00:10:49.624694 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-29 00:10:49.625143 | controller |   Attempting uninstall: setuptools
2025-09-29 00:10:49.630037 | controller |     Found existing installation: setuptools 62.6.0
2025-09-29 00:10:49.741221 | controller |     Uninstalling setuptools-62.6.0:
2025-09-29 00:10:49.756499 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-29 00:10:50.531521 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-29 00:10:50.737466 | controller |
2025-09-29 00:10:50.946886 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-29 00:10:50.946931 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-29 00:10:51.320089 | controller | ok: Runtime: 0:00:04.331747
2025-09-29 00:10:51.335451 | 
2025-09-29 00:10:51.335659 | TASK [Install pytest-forked into virtualenv]
2025-09-29 00:10:52.561789 | controller | Collecting pytest-forked
2025-09-29 00:10:52.649850 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-29 00:10:52.709577 | controller | Collecting py
2025-09-29 00:10:52.722601 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-29 00:10:52.759506 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00
2025-09-29 00:10:52.937252 | controller | Collecting pytest>=3.10
2025-09-29 00:10:52.953305 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-29 00:10:53.013632 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.4 MB/s eta 0:00:00
2025-09-29 00:10:53.067929 | controller | Collecting iniconfig>=1
2025-09-29 00:10:53.080545 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-29 00:10:53.147747 | controller | Collecting packaging>=20
2025-09-29 00:10:53.159753 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-29 00:10:53.174416 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.1 MB/s eta 0:00:00
2025-09-29 00:10:53.243522 | controller | Collecting pluggy<2,>=1.5
2025-09-29 00:10:53.256161 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-29 00:10:53.360580 | controller | Collecting pygments>=2.7.2
2025-09-29 00:10:53.373452 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-29 00:10:53.491954 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.5 MB/s eta 0:00:00
2025-09-29 00:10:53.617529 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-29 00:10:55.831208 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-09-29 00:10:55.847209 | controller |
2025-09-29 00:10:56.031383 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-29 00:10:56.031427 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-29 00:10:56.524449 | controller | ok: Runtime: 0:00:04.193314
2025-09-29 00:10:56.531805 | 
2025-09-29 00:10:56.531940 | TASK [Update pip]
2025-09-29 00:10:57.619379 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-29 00:10:57.907685 | controller | Collecting pip
2025-09-29 00:10:58.003839 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-29 00:10:58.200972 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.1 MB/s eta 0:00:00
2025-09-29 00:10:58.325134 | controller | Installing collected packages: pip
2025-09-29 00:10:58.325434 | controller |   Attempting uninstall: pip
2025-09-29 00:10:58.329788 | controller |     Found existing installation: pip 22.2.2
2025-09-29 00:10:58.587038 | controller |     Uninstalling pip-22.2.2:
2025-09-29 00:10:58.616565 | controller |       Successfully uninstalled pip-22.2.2
2025-09-29 00:11:00.318193 | controller | Successfully installed pip-25.2
2025-09-29 00:11:00.670298 | controller | ok: Runtime: 0:00:03.479564
2025-09-29 00:11:00.682626 | 
2025-09-29 00:11:00.682795 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-29 00:11:01.223191 | controller | changed
2025-09-29 00:11:01.234851 | 
2025-09-29 00:11:01.235010 | TASK [Install ansible into virtualenv]
2025-09-29 00:11:02.462893 | controller | Processing ./src/github.com/ansible/ansible
2025-09-29 00:11:02.469532 | controller |   Installing build dependencies: started
2025-09-29 00:11:04.533722 | controller |   Installing build dependencies: finished with status 'done'
2025-09-29 00:11:04.534702 | controller |   Getting requirements to build wheel: started
2025-09-29 00:11:06.142718 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-29 00:11:06.144022 | controller |   Preparing metadata (pyproject.toml): started
2025-09-29 00:11:07.052716 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-29 00:11:07.057428 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-09-29 00:11:07.062146 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-29 00:11:07.401086 | controller | ERROR
2025-09-29 00:11:07.401358 | controller | {
2025-09-29 00:11:07.401401 | controller |   "delta": "0:00:05.461151",
2025-09-29 00:11:07.401429 | controller |   "end": "2025-09-29 00:11:07.207331",
2025-09-29 00:11:07.401454 | controller |   "msg": "non-zero return code",
2025-09-29 00:11:07.401493 | controller |   "rc": 1,
2025-09-29 00:11:07.401518 | controller |   "start": "2025-09-29 00:11:01.746180"
2025-09-29 00:11:07.401540 | controller | }
failure
2025-09-29 00:11:07.403243 | 
2025-09-29 00:11:07.403329 | PLAY RECAP
2025-09-29 00:11:07.403418 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-29 00:11:07.403476 | 
2025-09-29 00:11:07.554565 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-29 00:11:07.555876 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-29 00:11:08.173319 | 
2025-09-29 00:11:08.173439 | PLAY [all]
2025-09-29 00:11:08.194709 | 
2025-09-29 00:11:08.194851 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-29 00:11:09.011113 | controller | changed: non-zero return code
2025-09-29 00:11:09.028212 | 
2025-09-29 00:11:09.028474 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-29 00:11:09.057816 | controller | skipping: Conditional result was False
2025-09-29 00:11:09.069663 | 
2025-09-29 00:11:09.069849 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-29 00:11:09.105406 | 
2025-09-29 00:11:09.105626 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-29 00:11:09.138987 | 
2025-09-29 00:11:09.139180 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-29 00:11:09.154928 | controller | skipping: Conditional result was False
2025-09-29 00:11:09.163594 | 
2025-09-29 00:11:09.163714 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-29 00:11:09.199069 | 
2025-09-29 00:11:09.199286 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-29 00:11:09.216188 | controller | skipping: Conditional result was False
2025-09-29 00:11:09.225072 | 
2025-09-29 00:11:09.225199 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-29 00:11:09.241556 | controller | skipping: Conditional result was False
2025-09-29 00:11:09.250511 | 
2025-09-29 00:11:09.250640 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-29 00:11:09.265812 | controller | skipping: Conditional result was False
2025-09-29 00:11:09.301967 | 
2025-09-29 00:11:09.302095 | PLAY RECAP
2025-09-29 00:11:09.302147 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-29 00:11:09.302175 | 
2025-09-29 00:11:09.436488 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-29 00:11:09.437629 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-29 00:11:10.079918 | 
2025-09-29 00:11:10.080050 | PLAY [all:!appliance*]
2025-09-29 00:11:10.102676 | 
2025-09-29 00:11:10.102797 | TASK [unregister the node]
2025-09-29 00:11:10.234887 | controller | skipping: Conditional result was False
2025-09-29 00:11:10.247411 | 
2025-09-29 00:11:10.247591 | TASK [include_role : fetch-output]
2025-09-29 00:11:10.285638 | controller | ok
2025-09-29 00:11:10.322841 | 
2025-09-29 00:11:10.322998 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-29 00:11:10.369106 | controller | skipping: Conditional result was False
2025-09-29 00:11:10.379281 | 
2025-09-29 00:11:10.379385 | TASK [fetch-output : Set log path for single node]
2025-09-29 00:11:10.422459 | controller | ok
2025-09-29 00:11:10.430108 | 
2025-09-29 00:11:10.430201 | LOOP [fetch-output : Ensure local output dirs]
2025-09-29 00:11:10.873790 | controller -> localhost | ok: "/var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/work/logs"
2025-09-29 00:11:11.175390 | controller -> localhost | changed: "/var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/work/artifacts"
2025-09-29 00:11:11.422797 | controller -> localhost | changed: "/var/lib/zuul/builds/d5707eadc3ee48a08b1faaeae891cfec/work/docs"
2025-09-29 00:11:11.451849 | 
2025-09-29 00:11:11.452052 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-29 00:11:12.636429 | controller | changed:
2025-09-29 00:11:12.636794 | controller | .d..t...... ./
2025-09-29 00:11:12.636836 | controller | cd+++++++++ controller/
2025-09-29 00:11:12.636875 | controller | changed: All items complete
2025-09-29 00:11:12.636897 | 
2025-09-29 00:11:13.706112 | controller | changed: .d..t...... ./
2025-09-29 00:11:14.706662 | controller | changed: .d..t...... ./
2025-09-29 00:11:14.733476 | 
2025-09-29 00:11:14.733632 | TASK [include_role : fetch-output-openshift]
2025-09-29 00:11:14.760290 | controller | skipping: Conditional result was False
2025-09-29 00:11:14.769071 | 
2025-09-29 00:11:14.769189 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-29 00:11:14.812120 | controller | skipping: Conditional result was False
2025-09-29 00:11:14.830885 | controller | skipping: Conditional result was False
2025-09-29 00:11:14.904611 | 
2025-09-29 00:11:14.904854 | PLAY [localhost]
2025-09-29 00:11:14.927858 | 
2025-09-29 00:11:14.927974 | TASK [Run Zuul manifest role]
2025-09-29 00:11:14.945692 | localhost | ok
2025-09-29 00:11:14.958852 | 
2025-09-29 00:11:14.958966 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-29 00:11:15.394372 | localhost | changed
2025-09-29 00:11:15.405779 | 
2025-09-29 00:11:15.405924 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-29 00:11:15.457462 | localhost | ok
2025-09-29 00:11:15.471059 | 
2025-09-29 00:11:15.471217 | TASK [Set zuul-log-path fact]
2025-09-29 00:11:15.495240 | localhost | ok
2025-09-29 00:11:15.514474 | 
2025-09-29 00:11:15.514685 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-29 00:11:15.559191 | localhost | ok
2025-09-29 00:11:15.576710 | 
2025-09-29 00:11:15.576961 | LOOP [Run upload-logs-swift role]
2025-09-29 00:11:15.616714 | localhost | Output suppressed because no_log was given
2025-09-29 00:11:15.644180 | 
2025-09-29 00:11:15.644318 | TASK [Set zuul-log-path fact]
2025-09-29 00:11:15.669879 | localhost | skipping: Conditional result was False
2025-09-29 00:11:15.675226 | 
2025-09-29 00:11:15.675308 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-29 00:11:16.174884 | localhost -> localhost | ok: Runtime: 0:00:00.005461
2025-09-29 00:11:16.181278 | 
2025-09-29 00:11:16.181355 | TASK [upload-logs-swift : Upload logs to swift]