2025-12-22 00:07:05.342838 | Job console starting...
2025-12-22 00:07:05.358126 | Updating repositories
2025-12-22 00:07:05.534257 | Preparing job workspace
2025-12-22 00:07:16.367667 | Running Ansible setup...
2025-12-22 00:07:22.161386 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-22 00:07:22.926249 | 
2025-12-22 00:07:22.926378 | PLAY [localhost]
2025-12-22 00:07:22.935275 | 
2025-12-22 00:07:22.935399 | TASK [Gathering Facts]
2025-12-22 00:07:25.075374 | localhost | ok
2025-12-22 00:07:25.090352 | 
2025-12-22 00:07:25.090451 | TASK [Setup log path fact]
2025-12-22 00:07:25.111666 | localhost | ok
2025-12-22 00:07:25.125712 | 
2025-12-22 00:07:25.125836 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-22 00:07:25.167648 | localhost | ok
2025-12-22 00:07:25.180826 | 
2025-12-22 00:07:25.180940 | TASK [emit-job-header : Print job information]
2025-12-22 00:07:25.225184 | # Job Information
2025-12-22 00:07:25.225363 | Ansible Version: 2.15.12
2025-12-22 00:07:25.225407 | Job: ansible-test-sanity-docker-milestone
2025-12-22 00:07:25.225704 | Pipeline: periodic
2025-12-22 00:07:25.225741 | Executor: ze01.softwarefactory-project.io
2025-12-22 00:07:25.225769 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-12-22 00:07:25.225799 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/5d0/ansible/5d07d109bdfc4e098aba6bb363001b09/
2025-12-22 00:07:25.225843 | Event ID: 7f35c592378340c19748c21b5a64baf3
2025-12-22 00:07:25.232665 | 
2025-12-22 00:07:25.232757 | LOOP [emit-job-header : Print node information]
2025-12-22 00:07:25.375370 | localhost | ok:
2025-12-22 00:07:25.375708 | localhost | # Node Information
2025-12-22 00:07:25.375767 | localhost | Inventory Hostname: controller
2025-12-22 00:07:25.375809 | localhost | Hostname: np0005568473
2025-12-22 00:07:25.375849 | localhost | Username: zuul
2025-12-22 00:07:25.375896 | localhost | Distro: Fedora 37
2025-12-22 00:07:25.375967 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-12-22 00:07:25.376007 | localhost | Region: ca-ymq-1
2025-12-22 00:07:25.376130 | localhost | Label: ansible-fedora-37-1vcpu
2025-12-22 00:07:25.376179 | localhost | Product Name: OpenStack Nova
2025-12-22 00:07:25.376225 | localhost | Interface IP: 162.253.55.218
2025-12-22 00:07:25.390571 | 
2025-12-22 00:07:25.390732 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-12-22 00:07:26.010450 | localhost -> localhost | changed
2025-12-22 00:07:26.022679 | 
2025-12-22 00:07:26.022833 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-12-22 00:07:27.507510 | localhost -> localhost | changed
2025-12-22 00:07:27.548835 | 
2025-12-22 00:07:27.549072 | PLAY [all:!appliance*]
2025-12-22 00:07:27.569977 | 
2025-12-22 00:07:27.570162 | TASK [include_role : start-zuul-console]
2025-12-22 00:07:27.597738 | controller | ok
2025-12-22 00:07:27.618430 | 
2025-12-22 00:07:27.618610 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-12-22 00:07:28.906493 | controller | ok
2025-12-22 00:07:28.929764 | 
2025-12-22 00:07:28.929954 | TASK [use-our-mirror : Retrieve the IP address]
2025-12-22 00:07:29.883302 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-12-22 00:07:29.896116 | 
2025-12-22 00:07:29.896263 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-12-22 00:07:30.690002 | controller | skipping: Conditional result was False
2025-12-22 00:07:30.700449 | 
2025-12-22 00:07:30.700615 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-12-22 00:07:30.737123 | controller | skipping: Conditional result was False
2025-12-22 00:07:30.746876 | 
2025-12-22 00:07:30.746967 | TASK [use-our-mirror : Create the podman configuration directory]
2025-12-22 00:07:30.784568 | controller | skipping: Conditional result was False
2025-12-22 00:07:30.800412 | 
2025-12-22 00:07:30.800593 | TASK [use-our-mirror : Copy the podman configuration]
2025-12-22 00:07:30.829058 | controller | skipping: Conditional result was False
2025-12-22 00:07:30.844871 | 
2025-12-22 00:07:30.845161 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-12-22 00:07:30.876868 | controller | skipping: Conditional result was False
2025-12-22 00:07:30.905323 | 
2025-12-22 00:07:30.905607 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-12-22 00:07:30.934488 | controller | skipping: Conditional result was False
2025-12-22 00:07:30.954672 | 
2025-12-22 00:07:30.954817 | TASK [Disable Fedora Modular]
2025-12-22 00:07:31.250434 | controller | changed
2025-12-22 00:07:31.265953 | 
2025-12-22 00:07:31.266225 | TASK [Enable EPEL]
2025-12-22 00:07:31.293809 | controller | skipping: Conditional result was False
2025-12-22 00:07:31.300853 | 
2025-12-22 00:07:31.300973 | TASK [Register the RHEL node]
2025-12-22 00:07:31.878834 | 
2025-12-22 00:07:31.879126 | TASK [Show the subscription-manager status]
2025-12-22 00:07:32.444634 | controller | skipping: Conditional result was False
2025-12-22 00:07:32.459971 | 
2025-12-22 00:07:32.460196 | TASK [Enable EPEL on RHEL]
2025-12-22 00:07:33.017105 | controller | skipping: Conditional result was False
2025-12-22 00:07:33.031464 | 
2025-12-22 00:07:33.031636 | TASK [Install git and tox]
2025-12-22 00:09:05.889197 | controller | changed
2025-12-22 00:09:05.904094 | 
2025-12-22 00:09:05.904238 | TASK [include_role : prepare-workspace]
2025-12-22 00:09:05.937236 | controller | ok
2025-12-22 00:09:05.975912 | 
2025-12-22 00:09:05.976070 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-12-22 00:09:06.227677 | controller | ok
2025-12-22 00:09:06.244178 | 
2025-12-22 00:09:06.244372 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-12-22 00:09:19.203375 | controller | Output suppressed because no_log was given
2025-12-22 00:09:19.214226 | 
2025-12-22 00:09:19.214305 | TASK [include_role : prepare-workspace-openshift]
2025-12-22 00:09:19.249178 | controller | skipping: Conditional result was False
2025-12-22 00:09:19.272180 | 
2025-12-22 00:09:19.272252 | PLAY [all:!appliance]
2025-12-22 00:09:19.289689 | 
2025-12-22 00:09:19.289769 | TASK [Run add-build-sshkey role (RSA)]
2025-12-22 00:09:19.321436 | controller | ok
2025-12-22 00:09:19.337625 | 
2025-12-22 00:09:19.337743 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-22 00:09:19.609331 | controller -> localhost | ok
2025-12-22 00:09:19.616044 | 
2025-12-22 00:09:19.616125 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-22 00:09:19.636891 | controller | ok
2025-12-22 00:09:19.651163 | controller | included: /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-22 00:09:19.657222 | 
2025-12-22 00:09:19.657283 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-22 00:09:20.112119 | controller -> localhost | Generating public/private rsa key pair.
2025-12-22 00:09:20.112427 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/work/5d07d109bdfc4e098aba6bb363001b09_id_rsa.
2025-12-22 00:09:20.112531 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/work/5d07d109bdfc4e098aba6bb363001b09_id_rsa.pub.
2025-12-22 00:09:20.112589 | controller -> localhost | The key fingerprint is:
2025-12-22 00:09:20.112637 | controller -> localhost | SHA256:dGXSsiZONkC3rbJERBCAvN8FMsHmD97YZdqdufWsnG4 zuul-build-sshkey
2025-12-22 00:09:20.112698 | controller -> localhost | The key's randomart image is:
2025-12-22 00:09:20.112772 | controller -> localhost | +---[RSA 2048]----+
2025-12-22 00:09:20.112848 | controller -> localhost | |..oo+=+ . ..o    |
2025-12-22 00:09:20.112902 | controller -> localhost | |.. = o.. o.+.    |
2025-12-22 00:09:20.112944 | controller -> localhost | |  + o o.o oo     |
2025-12-22 00:09:20.112983 | controller -> localhost | | . o . ==oo      |
2025-12-22 00:09:20.113066 | controller -> localhost | |  o B O+S+o      |
2025-12-22 00:09:20.113136 | controller -> localhost | |   + B +.+ .     |
2025-12-22 00:09:20.113191 | controller -> localhost | |      .   o o    |
2025-12-22 00:09:20.113262 | controller -> localhost | |         ..E.o   |
2025-12-22 00:09:20.113304 | controller -> localhost | |          o=.    |
2025-12-22 00:09:20.113350 | controller -> localhost | +----[SHA256]-----+
2025-12-22 00:09:20.113464 | controller -> localhost | ok: Runtime: 0:00:00.076961
2025-12-22 00:09:20.130565 | 
2025-12-22 00:09:20.130732 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-22 00:09:20.171415 | controller | ok
2025-12-22 00:09:20.194067 | controller | included: /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-22 00:09:20.208463 | 
2025-12-22 00:09:20.208564 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-22 00:09:20.236218 | controller | skipping: Conditional result was False
2025-12-22 00:09:20.246343 | 
2025-12-22 00:09:20.246486 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-22 00:09:20.728610 | controller | changed
2025-12-22 00:09:20.741956 | 
2025-12-22 00:09:20.742142 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-22 00:09:20.979062 | controller | ok
2025-12-22 00:09:20.984777 | 
2025-12-22 00:09:20.984842 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-22 00:09:21.645115 | controller | changed
2025-12-22 00:09:21.661140 | 
2025-12-22 00:09:21.661357 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-22 00:09:22.301753 | controller | changed
2025-12-22 00:09:22.310170 | 
2025-12-22 00:09:22.310293 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-22 00:09:22.337611 | controller | skipping: Conditional result was False
2025-12-22 00:09:22.347812 | 
2025-12-22 00:09:22.347929 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-22 00:09:22.783787 | controller -> localhost | changed
2025-12-22 00:09:22.796303 | 
2025-12-22 00:09:22.796407 | TASK [add-build-sshkey : Add back temp key]
2025-12-22 00:09:23.056764 | controller -> localhost | Identity added: /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/work/5d07d109bdfc4e098aba6bb363001b09_id_rsa (zuul-build-sshkey)
2025-12-22 00:09:23.057134 | controller -> localhost | ok: Runtime: 0:00:00.007777
2025-12-22 00:09:23.074097 | 
2025-12-22 00:09:23.074280 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-22 00:09:23.442562 | controller | ok
2025-12-22 00:09:23.455011 | 
2025-12-22 00:09:23.455216 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-22 00:09:23.493219 | controller | skipping: Conditional result was False
2025-12-22 00:09:23.523743 | 
2025-12-22 00:09:23.523909 | TASK [Run add-build-sshkey role (ECDSA)]
2025-12-22 00:09:23.549918 | controller | ok
2025-12-22 00:09:23.572305 | 
2025-12-22 00:09:23.572405 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-12-22 00:09:23.843414 | controller -> localhost | ok
2025-12-22 00:09:23.849950 | 
2025-12-22 00:09:23.850046 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-12-22 00:09:23.880087 | controller | ok
2025-12-22 00:09:23.895953 | controller | included: /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-12-22 00:09:23.902907 | 
2025-12-22 00:09:23.903041 | TASK [add-build-sshkey : Create Temp SSH key]
2025-12-22 00:09:24.274218 | controller -> localhost | Generating public/private ecdsa key pair.
2025-12-22 00:09:24.274392 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/work/5d07d109bdfc4e098aba6bb363001b09_id_ecdsa.
2025-12-22 00:09:24.274419 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/work/5d07d109bdfc4e098aba6bb363001b09_id_ecdsa.pub.
2025-12-22 00:09:24.274449 | controller -> localhost | The key fingerprint is:
2025-12-22 00:09:24.274469 | controller -> localhost | SHA256:nFv7cA41iG+yrbV+UW6eHQR5U/ftHceZQDZOHEWp5VA zuul-build-sshkey
2025-12-22 00:09:24.274489 | controller -> localhost | The key's randomart image is:
2025-12-22 00:09:24.274507 | controller -> localhost | +---[ECDSA 521]---+
2025-12-22 00:09:24.274526 | controller -> localhost | |            oB*E=|
2025-12-22 00:09:24.274543 | controller -> localhost | |            +=o**|
2025-12-22 00:09:24.274561 | controller -> localhost | |             .B+*|
2025-12-22 00:09:24.274579 | controller -> localhost | |       . o . ..++|
2025-12-22 00:09:24.274596 | controller -> localhost | |        S o oo. o|
2025-12-22 00:09:24.274614 | controller -> localhost | |         + o..o. |
2025-12-22 00:09:24.274631 | controller -> localhost | |        o B .+ o.|
2025-12-22 00:09:24.274648 | controller -> localhost | |         * B. o .|
2025-12-22 00:09:24.274665 | controller -> localhost | |        oo+.o    |
2025-12-22 00:09:24.274682 | controller -> localhost | +----[SHA256]-----+
2025-12-22 00:09:24.274726 | controller -> localhost | ok: Runtime: 0:00:00.015235
2025-12-22 00:09:24.281474 | 
2025-12-22 00:09:24.281556 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-12-22 00:09:24.311441 | controller | ok
2025-12-22 00:09:24.319225 | controller | included: /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-12-22 00:09:24.329459 | 
2025-12-22 00:09:24.329534 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-12-22 00:09:24.353956 | controller | skipping: Conditional result was False
2025-12-22 00:09:24.362151 | 
2025-12-22 00:09:24.362220 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-12-22 00:09:24.645140 | controller | changed
2025-12-22 00:09:24.662709 | 
2025-12-22 00:09:24.662913 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-12-22 00:09:24.904303 | controller | ok
2025-12-22 00:09:24.914627 | 
2025-12-22 00:09:24.914780 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-12-22 00:09:25.571693 | controller | changed
2025-12-22 00:09:25.580544 | 
2025-12-22 00:09:25.580684 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-12-22 00:09:26.216510 | controller | changed
2025-12-22 00:09:26.228062 | 
2025-12-22 00:09:26.228215 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-12-22 00:09:26.264824 | controller | skipping: Conditional result was False
2025-12-22 00:09:26.319120 | 
2025-12-22 00:09:26.319245 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-12-22 00:09:26.642914 | controller -> localhost | changed
2025-12-22 00:09:26.655442 | 
2025-12-22 00:09:26.655532 | TASK [add-build-sshkey : Add back temp key]
2025-12-22 00:09:27.014309 | controller -> localhost | Identity added: /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/work/5d07d109bdfc4e098aba6bb363001b09_id_ecdsa (zuul-build-sshkey)
2025-12-22 00:09:27.014978 | controller -> localhost | ok: Runtime: 0:00:00.008701
2025-12-22 00:09:27.030004 | 
2025-12-22 00:09:27.030199 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-12-22 00:09:27.247526 | controller | ok
2025-12-22 00:09:27.263195 | 
2025-12-22 00:09:27.263396 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-12-22 00:09:27.301797 | controller | skipping: Conditional result was False
2025-12-22 00:09:27.328296 | 
2025-12-22 00:09:27.328451 | TASK [include_role : remove-zuul-sshkey]
2025-12-22 00:09:27.355781 | controller | skipping: Conditional result was False
2025-12-22 00:09:27.375315 | 
2025-12-22 00:09:27.375483 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-12-22 00:09:27.639144 | controller | ok: "logs"
2025-12-22 00:09:27.639674 | controller | ok: All items complete
2025-12-22 00:09:27.639762 | 
2025-12-22 00:09:27.837589 | controller | ok: "artifacts"
2025-12-22 00:09:28.037395 | controller | ok: "docs"
2025-12-22 00:09:28.058519 | 
2025-12-22 00:09:28.058712 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-12-22 00:09:28.304305 | controller | changed: "logs"
2025-12-22 00:09:28.496073 | controller | changed: "artifacts"
2025-12-22 00:09:28.702233 | controller | changed: "docs"
2025-12-22 00:09:28.756382 | 
2025-12-22 00:09:28.756502 | PLAY RECAP
2025-12-22 00:09:28.756558 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-12-22 00:09:28.756593 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-12-22 00:09:28.756617 | 
2025-12-22 00:09:28.877369 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-12-22 00:09:28.879398 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-22 00:09:29.550080 | 
2025-12-22 00:09:29.550252 | PLAY [all]
2025-12-22 00:09:29.572735 | 
2025-12-22 00:09:29.572884 | TASK [Install binary dependencies]
2025-12-22 00:09:29.648203 | controller | ok
2025-12-22 00:09:29.678050 | 
2025-12-22 00:09:29.678213 | TASK [bindep : Include find tasks]
2025-12-22 00:09:29.718684 | controller | ok
2025-12-22 00:09:29.727267 | controller | included: /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-12-22 00:09:29.734191 | 
2025-12-22 00:09:29.734265 | TASK [bindep : Look for bindep.txt]
2025-12-22 00:09:30.109925 | controller | ok
2025-12-22 00:09:30.123898 | 
2025-12-22 00:09:30.124308 | TASK [bindep : Define bindep_file fact]
2025-12-22 00:09:30.152875 | controller | skipping: Conditional result was False
2025-12-22 00:09:30.169330 | 
2025-12-22 00:09:30.169557 | TASK [bindep : Look for other-requirements.txt]
2025-12-22 00:09:30.396243 | controller | ok
2025-12-22 00:09:30.413416 | 
2025-12-22 00:09:30.413633 | TASK [bindep : Define bindep_file fact]
2025-12-22 00:09:30.451963 | controller | skipping: Conditional result was False
2025-12-22 00:09:30.465971 | 
2025-12-22 00:09:30.466163 | TASK [bindep : Look for bindep fallback file]
2025-12-22 00:09:30.503922 | controller | skipping: Conditional result was False
2025-12-22 00:09:30.523883 | 
2025-12-22 00:09:30.524181 | TASK [bindep : Define bindep_file fact]
2025-12-22 00:09:30.561616 | controller | skipping: Conditional result was False
2025-12-22 00:09:30.570952 | 
2025-12-22 00:09:30.571101 | TASK [bindep : Include bindep tasks]
2025-12-22 00:09:30.596167 | controller | skipping: Conditional result was False
2025-12-22 00:09:30.605940 | 
2025-12-22 00:09:30.606166 | TASK [bindep : Include install tasks]
2025-12-22 00:09:30.632535 | controller | skipping: Conditional result was False
2025-12-22 00:09:30.641986 | 
2025-12-22 00:09:30.642132 | LOOP [bindep : Include package tasks]
2025-12-22 00:09:30.694263 | 
2025-12-22 00:09:30.694480 | TASK [Run test-setup role]
2025-12-22 00:09:30.718772 | controller | ok
2025-12-22 00:09:30.743278 | 
2025-12-22 00:09:30.743430 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-12-22 00:09:30.979605 | controller | ok
2025-12-22 00:09:30.986034 | 
2025-12-22 00:09:30.986103 | TASK [test-setup : Run tools/test-setup.sh]
2025-12-22 00:09:31.520616 | controller | skipping: Conditional result was False
2025-12-22 00:09:31.577344 | 
2025-12-22 00:09:31.577548 | PLAY RECAP
2025-12-22 00:09:31.577617 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-22 00:09:31.577647 | 
2025-12-22 00:09:31.695970 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-12-22 00:09:31.697862 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-22 00:09:32.329220 | 
2025-12-22 00:09:32.329393 | PLAY [controller]
2025-12-22 00:09:32.350854 | 
2025-12-22 00:09:32.351070 | TASK [Create the /root directory]
2025-12-22 00:09:32.737093 | controller | ok
2025-12-22 00:09:32.751755 | 
2025-12-22 00:09:32.751914 | TASK [Install glibc-langpack-en]
2025-12-22 00:09:36.685595 | controller | ok: Nothing to do
2025-12-22 00:09:36.691855 | 
2025-12-22 00:09:36.691936 | TASK [Ensure controller directory exists]
2025-12-22 00:09:36.920675 | controller | changed
2025-12-22 00:09:36.928772 | 
2025-12-22 00:09:36.928916 | TASK [Install container runtime]
2025-12-22 00:09:37.005435 | controller | ok
2025-12-22 00:09:37.055709 | 
2025-12-22 00:09:37.055855 | LOOP [ensure-podman : Find distribution installation]
2025-12-22 00:09:37.101315 | controller | ok: "/var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-12-22 00:09:37.109765 | controller | included: /var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-12-22 00:09:37.116425 | 
2025-12-22 00:09:37.116495 | TASK [ensure-podman : Install podman (RedHat)]
2025-12-22 00:10:44.681635 | controller | changed
2025-12-22 00:10:44.689284 | 
2025-12-22 00:10:44.689387 | TASK [ensure-podman : Fetch podman version]
2025-12-22 00:10:45.250763 | controller | Client:       Podman Engine
2025-12-22 00:10:45.250862 | controller | Version:      4.6.2
2025-12-22 00:10:45.250907 | controller | API Version:  4.6.2
2025-12-22 00:10:45.250949 | controller | Go Version:   go1.19.12
2025-12-22 00:10:45.251010 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-12-22 00:10:45.251054 | controller | OS/Arch:      linux/amd64
2025-12-22 00:10:45.725123 | controller | ok: Runtime: 0:00:00.191343
2025-12-22 00:10:45.740682 | 
2025-12-22 00:10:45.740832 | TASK [ensure-podman : Print podman version installed]
2025-12-22 00:10:45.776232 | Podman version: Client:       Podman Engine
2025-12-22 00:10:45.776447 | Version:      4.6.2
2025-12-22 00:10:45.776492 | API Version:  4.6.2
2025-12-22 00:10:45.776522 | Go Version:   go1.19.12
2025-12-22 00:10:45.776548 | Built:        Mon Aug 28 19:38:31 2023
2025-12-22 00:10:45.776575 | OS/Arch:      linux/amd64
2025-12-22 00:10:45.789578 | 
2025-12-22 00:10:45.789740 | TASK [ensure-podman : Validate podman engine]
2025-12-22 00:10:46.336619 | controller | skipping: Conditional result was False
2025-12-22 00:10:46.350538 | 
2025-12-22 00:10:46.350694 | TASK [ensure-podman : Set up docker compatability socket]
2025-12-22 00:10:46.377826 | controller | skipping: Conditional result was False
2025-12-22 00:10:46.409382 | 
2025-12-22 00:10:46.409620 | TASK [Ensure python3.8 is present]
2025-12-22 00:10:46.439227 | controller | skipping: Conditional result was False
2025-12-22 00:10:46.453288 | 
2025-12-22 00:10:46.453487 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-12-22 00:10:46.480497 | controller | ok
2025-12-22 00:10:46.510569 | 
2025-12-22 00:10:46.510735 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-12-22 00:10:48.036154 | controller | ok: Nothing to do
2025-12-22 00:10:48.051582 | 
2025-12-22 00:10:48.051807 | TASK [our-ensure-python : Also install python3-devel]
2025-12-22 00:10:59.691145 | controller | changed
2025-12-22 00:10:59.715632 | 
2025-12-22 00:10:59.715956 | TASK [Run ensure-virtualenv role]
2025-12-22 00:10:59.739589 | controller | ok
2025-12-22 00:10:59.770428 | 
2025-12-22 00:10:59.770538 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-12-22 00:11:00.013838 | controller | /usr/bin/virtualenv
2025-12-22 00:11:00.339289 | controller | ok: Runtime: 0:00:00.004823
2025-12-22 00:11:00.352446 | 
2025-12-22 00:11:00.352577 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-12-22 00:11:00.386722 | controller | skipping: Conditional result was False
2025-12-22 00:11:00.387194 | controller | ok: All items complete
2025-12-22 00:11:00.387254 | 
2025-12-22 00:11:00.414607 | 
2025-12-22 00:11:00.414771 | TASK [Find the full path of the Python interpreter]
2025-12-22 00:11:00.651617 | controller | /usr/bin/python3
2025-12-22 00:11:00.962090 | controller | ok
2025-12-22 00:11:00.975294 | 
2025-12-22 00:11:00.975472 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-12-22 00:11:01.817444 | controller | created virtual environment CPython3.11.0.final.0-64 in 493ms
2025-12-22 00:11:01.833856 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-12-22 00:11:01.833896 | 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-12-22 00:11:01.833906 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-12-22 00:11:01.833921 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-12-22 00:11:02.038806 | controller | changed
2025-12-22 00:11:02.047394 | 
2025-12-22 00:11:02.047490 | TASK [Set selinux package]
2025-12-22 00:11:02.084188 | controller | ok
2025-12-22 00:11:02.096718 | 
2025-12-22 00:11:02.096900 | TASK [Set selinux package (Fedora)]
2025-12-22 00:11:02.139145 | controller | ok
2025-12-22 00:11:02.150673 | 
2025-12-22 00:11:02.150807 | TASK [Install selinux into virtualenv]
2025-12-22 00:11:27.666930 | controller | Collecting selinux-please-lie-to-me
2025-12-22 00:11:39.931756 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-12-22 00:11:40.242128 | controller | Collecting setuptools<50.0.0
2025-12-22 00:11:40.248279 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-12-22 00:11:40.288208 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.5 MB/s eta 0:00:00
2025-12-22 00:11:40.370696 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-12-22 00:11:40.370907 | controller |   Attempting uninstall: setuptools
2025-12-22 00:11:40.373320 | controller |     Found existing installation: setuptools 62.6.0
2025-12-22 00:11:40.432105 | controller |     Uninstalling setuptools-62.6.0:
2025-12-22 00:11:40.440015 | controller |       Successfully uninstalled setuptools-62.6.0
2025-12-22 00:11:40.785752 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-12-22 00:11:57.093360 | controller |
2025-12-22 00:11:57.172852 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-22 00:11:57.172890 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-22 00:11:57.214197 | controller | ok: Runtime: 0:00:54.811631
2025-12-22 00:11:57.226755 | 
2025-12-22 00:11:57.226947 | TASK [Install pytest-forked into virtualenv]
2025-12-22 00:12:09.348126 | controller | Collecting pytest-forked
2025-12-22 00:12:21.702900 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-12-22 00:12:21.747041 | controller | Collecting py
2025-12-22 00:12:21.750606 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-12-22 00:12:21.783850 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00
2025-12-22 00:12:21.896502 | controller | Collecting pytest>=3.10
2025-12-22 00:12:21.903340 | controller |   Downloading pytest-9.0.2-py3-none-any.whl (374 kB)
2025-12-22 00:12:21.921479 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 24.1 MB/s eta 0:00:00
2025-12-22 00:12:21.957870 | controller | Collecting iniconfig>=1.0.1
2025-12-22 00:12:21.961693 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-12-22 00:12:22.001090 | controller | Collecting packaging>=22
2025-12-22 00:12:22.004438 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-12-22 00:12:22.010126 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 17.5 MB/s eta 0:00:00
2025-12-22 00:12:22.042548 | controller | Collecting pluggy<2,>=1.5
2025-12-22 00:12:22.045785 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-12-22 00:12:22.091904 | controller | Collecting pygments>=2.7.2
2025-12-22 00:12:22.096234 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-12-22 00:12:22.123584 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 70.0 MB/s eta 0:00:00
2025-12-22 00:12:22.191545 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-12-22 00:12:23.214829 | 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.2 pytest-forked-1.6.0
2025-12-22 00:12:23.223243 | controller |
2025-12-22 00:12:23.288089 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-12-22 00:12:23.288153 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-12-22 00:12:23.332123 | controller | ok: Runtime: 0:00:25.833668
2025-12-22 00:12:23.346292 | 
2025-12-22 00:12:23.346466 | TASK [Update pip]
2025-12-22 00:12:23.891817 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-12-22 00:12:45.940348 | controller | Collecting pip
2025-12-22 00:12:58.261190 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-12-22 00:12:58.324863 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 30.4 MB/s eta 0:00:00
2025-12-22 00:12:58.387007 | controller | Installing collected packages: pip
2025-12-22 00:12:58.387219 | controller |   Attempting uninstall: pip
2025-12-22 00:12:58.389350 | controller |     Found existing installation: pip 22.2.2
2025-12-22 00:12:58.526219 | controller |     Uninstalling pip-22.2.2:
2025-12-22 00:12:58.540844 | controller |       Successfully uninstalled pip-22.2.2
2025-12-22 00:12:59.341892 | controller | Successfully installed pip-25.3
2025-12-22 00:12:59.462399 | controller | ok: Runtime: 0:00:35.813027
2025-12-22 00:12:59.474979 | 
2025-12-22 00:12:59.475155 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-12-22 00:12:59.699941 | controller | changed
2025-12-22 00:12:59.712501 | 
2025-12-22 00:12:59.712633 | TASK [Install ansible into virtualenv]
2025-12-22 00:13:00.259022 | controller | Processing ./src/github.com/ansible/ansible
2025-12-22 00:13:00.262304 | controller |   Installing build dependencies: started
2025-12-22 00:13:23.686872 | controller |   Installing build dependencies: finished with status 'done'
2025-12-22 00:13:23.690235 | controller |   Getting requirements to build wheel: started
2025-12-22 00:13:24.530992 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-12-22 00:13:24.534077 | controller |   Preparing metadata (pyproject.toml): started
2025-12-22 00:13:25.004457 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-12-22 00:13:25.010761 | 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-12-22 00:13:25.014604 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-12-22 00:13:25.328248 | controller | ERROR
2025-12-22 00:13:25.328460 | controller | {
2025-12-22 00:13:25.328490 | controller |   "delta": "0:00:25.125274",
2025-12-22 00:13:25.328509 | controller |   "end": "2025-12-22 00:13:25.106860",
2025-12-22 00:13:25.328527 | controller |   "msg": "non-zero return code",
2025-12-22 00:13:25.328553 | controller |   "rc": 1,
2025-12-22 00:13:25.328570 | controller |   "start": "2025-12-22 00:12:59.981586"
2025-12-22 00:13:25.328586 | controller | }
failure
2025-12-22 00:13:25.330384 | 
2025-12-22 00:13:25.330442 | PLAY RECAP
2025-12-22 00:13:25.330486 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-12-22 00:13:25.330511 | 
2025-12-22 00:13:25.437869 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-12-22 00:13:25.438962 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-22 00:13:26.085432 | 
2025-12-22 00:13:26.085563 | PLAY [all]
2025-12-22 00:13:26.110775 | 
2025-12-22 00:13:26.110924 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-12-22 00:13:26.385546 | controller | changed: non-zero return code
2025-12-22 00:13:26.399220 | 
2025-12-22 00:13:26.399461 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-12-22 00:13:26.428643 | controller | skipping: Conditional result was False
2025-12-22 00:13:26.445827 | 
2025-12-22 00:13:26.446094 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-12-22 00:13:26.488356 | 
2025-12-22 00:13:26.488628 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-12-22 00:13:26.531799 | 
2025-12-22 00:13:26.532107 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-12-22 00:13:26.559685 | controller | skipping: Conditional result was False
2025-12-22 00:13:26.575757 | 
2025-12-22 00:13:26.575946 | LOOP [fetch-subunit-output : Generate subunit file]
2025-12-22 00:13:26.616401 | 
2025-12-22 00:13:26.616727 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-12-22 00:13:26.644174 | controller | skipping: Conditional result was False
2025-12-22 00:13:26.657973 | 
2025-12-22 00:13:26.658191 | TASK [fetch-subunit-output : Remove the temporary file]
2025-12-22 00:13:26.685292 | controller | skipping: Conditional result was False
2025-12-22 00:13:26.698784 | 
2025-12-22 00:13:26.698997 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-12-22 00:13:26.725912 | controller | skipping: Conditional result was False
2025-12-22 00:13:26.776302 | 
2025-12-22 00:13:26.776413 | PLAY RECAP
2025-12-22 00:13:26.776471 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-12-22 00:13:26.776502 | 
2025-12-22 00:13:26.877748 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-12-22 00:13:26.878698 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-12-22 00:13:27.507412 | 
2025-12-22 00:13:27.507544 | PLAY [all:!appliance*]
2025-12-22 00:13:27.531562 | 
2025-12-22 00:13:27.531711 | TASK [unregister the node]
2025-12-22 00:13:28.064658 | controller | skipping: Conditional result was False
2025-12-22 00:13:28.077952 | 
2025-12-22 00:13:28.078184 | TASK [include_role : fetch-output]
2025-12-22 00:13:28.131369 | controller | ok
2025-12-22 00:13:28.170342 | 
2025-12-22 00:13:28.170494 | TASK [fetch-output : Set log path for multiple nodes]
2025-12-22 00:13:28.228135 | controller | skipping: Conditional result was False
2025-12-22 00:13:28.238888 | 
2025-12-22 00:13:28.239047 | TASK [fetch-output : Set log path for single node]
2025-12-22 00:13:28.283709 | controller | ok
2025-12-22 00:13:28.291864 | 
2025-12-22 00:13:28.291962 | LOOP [fetch-output : Ensure local output dirs]
2025-12-22 00:13:28.686621 | controller -> localhost | ok: "/var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/work/logs"
2025-12-22 00:13:28.921275 | controller -> localhost | changed: "/var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/work/artifacts"
2025-12-22 00:13:29.132400 | controller -> localhost | changed: "/var/lib/zuul/builds/5d07d109bdfc4e098aba6bb363001b09/work/docs"
2025-12-22 00:13:29.148405 | 
2025-12-22 00:13:29.148480 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-12-22 00:13:29.875327 | controller | changed:
2025-12-22 00:13:29.875555 | controller | .d..t...... ./
2025-12-22 00:13:29.875593 | controller | cd+++++++++ controller/
2025-12-22 00:13:29.875638 | controller | changed: All items complete
2025-12-22 00:13:29.875665 | 
2025-12-22 00:13:30.394151 | controller | changed: .d..t...... ./
2025-12-22 00:13:30.891912 | controller | changed: .d..t...... ./
2025-12-22 00:13:30.921683 | 
2025-12-22 00:13:30.921877 | TASK [include_role : fetch-output-openshift]
2025-12-22 00:13:30.947950 | controller | skipping: Conditional result was False
2025-12-22 00:13:30.955952 | 
2025-12-22 00:13:30.956059 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-12-22 00:13:30.993891 | controller | skipping: Conditional result was False
2025-12-22 00:13:31.004641 | controller | skipping: Conditional result was False
2025-12-22 00:13:31.052325 | 
2025-12-22 00:13:31.052445 | PLAY [localhost]
2025-12-22 00:13:31.068398 | 
2025-12-22 00:13:31.068476 | TASK [Run Zuul manifest role]
2025-12-22 00:13:31.086292 | localhost | ok
2025-12-22 00:13:31.105113 | 
2025-12-22 00:13:31.105223 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-12-22 00:13:31.597207 | localhost | changed
2025-12-22 00:13:31.607532 | 
2025-12-22 00:13:31.607668 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-12-22 00:13:31.645328 | localhost | ok
2025-12-22 00:13:31.664084 | 
2025-12-22 00:13:31.664274 | TASK [Set zuul-log-path fact]
2025-12-22 00:13:31.688469 | localhost | ok
2025-12-22 00:13:31.708193 | 
2025-12-22 00:13:31.708331 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-12-22 00:13:31.741831 | localhost | ok
2025-12-22 00:13:31.753839 | 
2025-12-22 00:13:31.753953 | LOOP [Run upload-logs-swift role]
2025-12-22 00:13:31.799970 | localhost | Output suppressed because no_log was given
2025-12-22 00:13:31.839865 | 
2025-12-22 00:13:31.840066 | TASK [Set zuul-log-path fact]
2025-12-22 00:13:31.875860 | localhost | skipping: Conditional result was False
2025-12-22 00:13:31.883239 | 
2025-12-22 00:13:31.883347 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-12-22 00:13:32.307527 | localhost -> localhost | ok: Runtime: 0:00:00.009104
2025-12-22 00:13:32.327499 | 
2025-12-22 00:13:32.327698 | TASK [upload-logs-swift : Upload logs to swift]