2025-09-24 00:17:26.739824 | Job console starting...
2025-09-24 00:17:26.756663 | Updating repositories
2025-09-24 00:17:27.373805 | Preparing job workspace
2025-09-24 00:17:31.532447 | Running Ansible setup...
2025-09-24 00:17:39.871219 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-24 00:17:40.588720 | 
2025-09-24 00:17:40.588866 | PLAY [localhost]
2025-09-24 00:17:40.597893 | 
2025-09-24 00:17:40.598004 | TASK [Gathering Facts]
2025-09-24 00:17:41.601189 | localhost | ok
2025-09-24 00:17:41.615323 | 
2025-09-24 00:17:41.615416 | TASK [Setup log path fact]
2025-09-24 00:17:41.634540 | localhost | ok
2025-09-24 00:17:41.647934 | 
2025-09-24 00:17:41.648046 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-24 00:17:41.686870 | localhost | ok
2025-09-24 00:17:41.700733 | 
2025-09-24 00:17:41.700896 | TASK [emit-job-header : Print job information]
2025-09-24 00:17:41.757196 | # Job Information
2025-09-24 00:17:41.757474 | Ansible Version: 2.15.12
2025-09-24 00:17:41.757544 | Job: ansible-test-sanity-docker-devel
2025-09-24 00:17:41.757591 | Pipeline: periodic
2025-09-24 00:17:41.757635 | Executor: ze04.softwarefactory-project.io
2025-09-24 00:17:41.757704 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-09-24 00:17:41.757762 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/2f9/ansible/2f9c844e26964be0a631155d61cf4cf9/
2025-09-24 00:17:41.757806 | Event ID: 3b09a8e0ff9c49ffb90e8d2a452c8a0a
2025-09-24 00:17:41.763307 | 
2025-09-24 00:17:41.763398 | LOOP [emit-job-header : Print node information]
2025-09-24 00:17:41.891279 | localhost | ok:
2025-09-24 00:17:41.891622 | localhost | # Node Information
2025-09-24 00:17:41.891784 | localhost | Inventory Hostname: controller
2025-09-24 00:17:41.891931 | localhost | Hostname: np0005447829
2025-09-24 00:17:41.891964 | localhost | Username: zuul
2025-09-24 00:17:41.892001 | localhost | Distro: Fedora 37
2025-09-24 00:17:41.892029 | localhost | Provider: ansible-vexxhost-ams1
2025-09-24 00:17:41.892055 | localhost | Region: ams1
2025-09-24 00:17:41.892080 | localhost | Label: ansible-fedora-37-1vcpu
2025-09-24 00:17:41.892104 | localhost | Product Name: OpenStack Nova
2025-09-24 00:17:41.892129 | localhost | Interface IP: 38.129.16.97
2025-09-24 00:17:41.912758 | 
2025-09-24 00:17:41.912892 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-09-24 00:17:42.389119 | localhost -> localhost | changed
2025-09-24 00:17:42.402408 | 
2025-09-24 00:17:42.402537 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-09-24 00:17:43.319398 | localhost -> localhost | changed
2025-09-24 00:17:43.340092 | 
2025-09-24 00:17:43.340239 | PLAY [all:!appliance*]
2025-09-24 00:17:43.356565 | 
2025-09-24 00:17:43.356638 | TASK [include_role : start-zuul-console]
2025-09-24 00:17:43.376912 | controller | ok
2025-09-24 00:17:43.391347 | 
2025-09-24 00:17:43.391423 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-09-24 00:17:44.477602 | controller | ok
2025-09-24 00:17:44.502331 | 
2025-09-24 00:17:44.502510 | TASK [use-our-mirror : Retrieve the IP address]
2025-09-24 00:17:46.932582 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-09-24 00:17:46.945855 | 
2025-09-24 00:17:46.945991 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-09-24 00:17:47.326019 | controller | skipping: Conditional result was False
2025-09-24 00:17:47.346938 | 
2025-09-24 00:17:47.347214 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-09-24 00:17:47.387374 | controller | skipping: Conditional result was False
2025-09-24 00:17:47.402073 | 
2025-09-24 00:17:47.402272 | TASK [use-our-mirror : Create the podman configuration directory]
2025-09-24 00:17:47.429873 | controller | skipping: Conditional result was False
2025-09-24 00:17:47.445156 | 
2025-09-24 00:17:47.445361 | TASK [use-our-mirror : Copy the podman configuration]
2025-09-24 00:17:47.473647 | controller | skipping: Conditional result was False
2025-09-24 00:17:47.483826 | 
2025-09-24 00:17:47.483970 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-09-24 00:17:47.510005 | controller | skipping: Conditional result was False
2025-09-24 00:17:47.523242 | 
2025-09-24 00:17:47.523461 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-09-24 00:17:47.550116 | controller | skipping: Conditional result was False
2025-09-24 00:17:47.563310 | 
2025-09-24 00:17:47.563427 | TASK [Disable Fedora Modular]
2025-09-24 00:17:48.935055 | controller | changed
2025-09-24 00:17:48.941020 | 
2025-09-24 00:17:48.941113 | TASK [Enable EPEL]
2025-09-24 00:17:48.956003 | controller | skipping: Conditional result was False
2025-09-24 00:17:48.962853 | 
2025-09-24 00:17:48.962955 | TASK [Register the RHEL node]
2025-09-24 00:17:49.382188 | 
2025-09-24 00:17:49.382476 | TASK [Show the subscription-manager status]
2025-09-24 00:17:49.790540 | controller | skipping: Conditional result was False
2025-09-24 00:17:49.805719 | 
2025-09-24 00:17:49.805961 | TASK [Enable EPEL on RHEL]
2025-09-24 00:17:50.206832 | controller | skipping: Conditional result was False
2025-09-24 00:17:50.224588 | 
2025-09-24 00:17:50.224781 | TASK [Install git and tox]
2025-09-24 00:20:17.681261 | controller | changed
2025-09-24 00:20:17.689998 | 
2025-09-24 00:20:17.690086 | TASK [include_role : prepare-workspace]
2025-09-24 00:20:17.724734 | controller | ok
2025-09-24 00:20:17.756871 | 
2025-09-24 00:20:17.757017 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-09-24 00:20:18.668937 | controller | ok
2025-09-24 00:20:18.678774 | 
2025-09-24 00:20:18.678915 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-09-24 00:20:34.321305 | controller | Output suppressed because no_log was given
2025-09-24 00:20:34.347479 | 
2025-09-24 00:20:34.347656 | TASK [include_role : prepare-workspace-openshift]
2025-09-24 00:20:34.367226 | controller | skipping: Conditional result was False
2025-09-24 00:20:34.400334 | 
2025-09-24 00:20:34.400463 | PLAY [all:!appliance]
2025-09-24 00:20:34.423920 | 
2025-09-24 00:20:34.424013 | TASK [Run add-build-sshkey role (RSA)]
2025-09-24 00:20:34.465991 | controller | ok
2025-09-24 00:20:34.481099 | 
2025-09-24 00:20:34.481173 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-24 00:20:34.763224 | controller -> localhost | ok
2025-09-24 00:20:34.778430 | 
2025-09-24 00:20:34.778607 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-24 00:20:34.818529 | controller | ok
2025-09-24 00:20:34.849128 | controller | included: /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-24 00:20:34.858824 | 
2025-09-24 00:20:34.858982 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-24 00:20:35.457911 | controller -> localhost | Generating public/private rsa key pair.
2025-09-24 00:20:35.458305 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/work/2f9c844e26964be0a631155d61cf4cf9_id_rsa.
2025-09-24 00:20:35.458369 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/work/2f9c844e26964be0a631155d61cf4cf9_id_rsa.pub.
2025-09-24 00:20:35.458416 | controller -> localhost | The key fingerprint is:
2025-09-24 00:20:35.458460 | controller -> localhost | SHA256:D/nw9YErDutz8nF5JMwByIV7J2ZQC/ViTbVKQe51SZA zuul-build-sshkey
2025-09-24 00:20:35.458502 | controller -> localhost | The key's randomart image is:
2025-09-24 00:20:35.458544 | controller -> localhost | +---[RSA 2048]----+
2025-09-24 00:20:35.458584 | controller -> localhost | |       ..*=.+o+. |
2025-09-24 00:20:35.458626 | controller -> localhost | |        =. B E...|
2025-09-24 00:20:35.458666 | controller -> localhost | |         o+ * o..|
2025-09-24 00:20:35.458770 | controller -> localhost | |        .o=*.= . |
2025-09-24 00:20:35.458815 | controller -> localhost | |        S+ oO o  |
2025-09-24 00:20:35.458893 | controller -> localhost | |         * . * . |
2025-09-24 00:20:35.458974 | controller -> localhost | |        . * + o  |
2025-09-24 00:20:35.459018 | controller -> localhost | |        o+.+ .   |
2025-09-24 00:20:35.459060 | controller -> localhost | |       .o=o      |
2025-09-24 00:20:35.459105 | controller -> localhost | +----[SHA256]-----+
2025-09-24 00:20:35.459220 | controller -> localhost | ok: Runtime: 0:00:00.219072
2025-09-24 00:20:35.473483 | 
2025-09-24 00:20:35.473612 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-24 00:20:35.502732 | controller | ok
2025-09-24 00:20:35.523436 | controller | included: /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-24 00:20:35.536526 | 
2025-09-24 00:20:35.536608 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-24 00:20:35.561661 | controller | skipping: Conditional result was False
2025-09-24 00:20:35.570720 | 
2025-09-24 00:20:35.570814 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-24 00:20:36.644012 | controller | changed
2025-09-24 00:20:36.652350 | 
2025-09-24 00:20:36.652443 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-24 00:20:37.312990 | controller | ok
2025-09-24 00:20:37.321128 | 
2025-09-24 00:20:37.321236 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-24 00:20:40.561098 | controller | changed
2025-09-24 00:20:40.569477 | 
2025-09-24 00:20:40.569584 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-24 00:20:43.824325 | controller | changed
2025-09-24 00:20:43.841167 | 
2025-09-24 00:20:43.841357 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-24 00:20:43.869318 | controller | skipping: Conditional result was False
2025-09-24 00:20:43.878676 | 
2025-09-24 00:20:43.878817 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-24 00:20:44.365995 | controller -> localhost | changed
2025-09-24 00:20:44.378494 | 
2025-09-24 00:20:44.378607 | TASK [add-build-sshkey : Add back temp key]
2025-09-24 00:20:44.725400 | controller -> localhost | Identity added: /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/work/2f9c844e26964be0a631155d61cf4cf9_id_rsa (zuul-build-sshkey)
2025-09-24 00:20:44.725669 | controller -> localhost | ok: Runtime: 0:00:00.011923
2025-09-24 00:20:44.733752 | 
2025-09-24 00:20:44.733832 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-24 00:20:45.776837 | controller | ok
2025-09-24 00:20:45.788823 | 
2025-09-24 00:20:45.788964 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-24 00:20:45.825923 | controller | skipping: Conditional result was False
2025-09-24 00:20:45.854614 | 
2025-09-24 00:20:45.854844 | TASK [Run add-build-sshkey role (ECDSA)]
2025-09-24 00:20:45.885142 | controller | ok
2025-09-24 00:20:45.915025 | 
2025-09-24 00:20:45.915164 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-09-24 00:20:46.240265 | controller -> localhost | ok
2025-09-24 00:20:46.254939 | 
2025-09-24 00:20:46.255127 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-09-24 00:20:46.307872 | controller | ok
2025-09-24 00:20:46.335055 | controller | included: /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-09-24 00:20:46.344837 | 
2025-09-24 00:20:46.344929 | TASK [add-build-sshkey : Create Temp SSH key]
2025-09-24 00:20:46.708481 | controller -> localhost | Generating public/private ecdsa key pair.
2025-09-24 00:20:46.708733 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/work/2f9c844e26964be0a631155d61cf4cf9_id_ecdsa.
2025-09-24 00:20:46.708763 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/work/2f9c844e26964be0a631155d61cf4cf9_id_ecdsa.pub.
2025-09-24 00:20:46.708794 | controller -> localhost | The key fingerprint is:
2025-09-24 00:20:46.708815 | controller -> localhost | SHA256:To9gB9EmKmb4yQWFe7jf5wTUP1MPiIG2LIuB8o10IGw zuul-build-sshkey
2025-09-24 00:20:46.708835 | controller -> localhost | The key's randomart image is:
2025-09-24 00:20:46.708853 | controller -> localhost | +---[ECDSA 521]---+
2025-09-24 00:20:46.708872 | controller -> localhost | |.  o. .o.        |
2025-09-24 00:20:46.708890 | controller -> localhost | |.E+   +ooo .     |
2025-09-24 00:20:46.708907 | controller -> localhost | |.+ = +o+o . o    |
2025-09-24 00:20:46.708925 | controller -> localhost | |+ O *.o. . . o   |
2025-09-24 00:20:46.708942 | controller -> localhost | |.B % o+ S +   .  |
2025-09-24 00:20:46.708959 | controller -> localhost | |  O o. * o o     |
2025-09-24 00:20:46.708976 | controller -> localhost | |   . .  + .      |
2025-09-24 00:20:46.708993 | controller -> localhost | |    . ...        |
2025-09-24 00:20:46.709010 | controller -> localhost | |       o.        |
2025-09-24 00:20:46.709028 | controller -> localhost | +----[SHA256]-----+
2025-09-24 00:20:46.709081 | controller -> localhost | ok: Runtime: 0:00:00.009099
2025-09-24 00:20:46.715805 | 
2025-09-24 00:20:46.715869 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-09-24 00:20:46.746849 | controller | ok
2025-09-24 00:20:46.756729 | controller | included: /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-09-24 00:20:46.821217 | 
2025-09-24 00:20:46.821438 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-09-24 00:20:46.849745 | controller | skipping: Conditional result was False
2025-09-24 00:20:46.867836 | 
2025-09-24 00:20:46.868103 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-09-24 00:20:47.880753 | controller | changed
2025-09-24 00:20:47.889105 | 
2025-09-24 00:20:47.889200 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-09-24 00:20:48.606104 | controller | ok
2025-09-24 00:20:48.612264 | 
2025-09-24 00:20:48.612334 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-09-24 00:20:51.796855 | controller | changed
2025-09-24 00:20:51.810979 | 
2025-09-24 00:20:51.811127 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-09-24 00:20:54.992626 | controller | changed
2025-09-24 00:20:55.006043 | 
2025-09-24 00:20:55.006213 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-09-24 00:20:55.045113 | controller | skipping: Conditional result was False
2025-09-24 00:20:55.059877 | 
2025-09-24 00:20:55.060052 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-09-24 00:20:55.385524 | controller -> localhost | changed
2025-09-24 00:20:55.400233 | 
2025-09-24 00:20:55.400378 | TASK [add-build-sshkey : Add back temp key]
2025-09-24 00:20:55.771961 | controller -> localhost | Identity added: /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/work/2f9c844e26964be0a631155d61cf4cf9_id_ecdsa (zuul-build-sshkey)
2025-09-24 00:20:55.772375 | controller -> localhost | ok: Runtime: 0:00:00.015975
2025-09-24 00:20:55.780414 | 
2025-09-24 00:20:55.780511 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-09-24 00:20:56.543512 | controller | ok
2025-09-24 00:20:56.561176 | 
2025-09-24 00:20:56.561416 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-09-24 00:20:56.612563 | controller | skipping: Conditional result was False
2025-09-24 00:20:56.646721 | 
2025-09-24 00:20:56.647096 | TASK [include_role : remove-zuul-sshkey]
2025-09-24 00:20:56.688008 | controller | skipping: Conditional result was False
2025-09-24 00:20:56.697238 | 
2025-09-24 00:20:56.697453 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-09-24 00:20:57.442582 | controller | ok: "logs"
2025-09-24 00:20:57.443452 | controller | ok: All items complete
2025-09-24 00:20:57.443643 | 
2025-09-24 00:20:58.185519 | controller | ok: "artifacts"
2025-09-24 00:20:58.896765 | controller | ok: "docs"
2025-09-24 00:20:58.920467 | 
2025-09-24 00:20:58.920606 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-09-24 00:20:59.693279 | controller | changed: "logs"
2025-09-24 00:21:00.412392 | controller | changed: "artifacts"
2025-09-24 00:21:01.069831 | controller | changed: "docs"
2025-09-24 00:21:01.104766 | 
2025-09-24 00:21:01.104902 | PLAY RECAP
2025-09-24 00:21:01.104949 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-09-24 00:21:01.104978 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-09-24 00:21:01.105000 | 
2025-09-24 00:21:01.285918 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-09-24 00:21:01.287915 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-24 00:21:01.931729 | 
2025-09-24 00:21:01.931951 | PLAY [all]
2025-09-24 00:21:01.958792 | 
2025-09-24 00:21:01.958983 | TASK [Install binary dependencies]
2025-09-24 00:21:02.042502 | controller | ok
2025-09-24 00:21:02.066072 | 
2025-09-24 00:21:02.066273 | TASK [bindep : Include find tasks]
2025-09-24 00:21:02.111563 | controller | ok
2025-09-24 00:21:02.124203 | controller | included: /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-09-24 00:21:02.134515 | 
2025-09-24 00:21:02.134658 | TASK [bindep : Look for bindep.txt]
2025-09-24 00:21:03.241713 | controller | ok
2025-09-24 00:21:03.248260 | 
2025-09-24 00:21:03.248338 | TASK [bindep : Define bindep_file fact]
2025-09-24 00:21:03.274496 | controller | skipping: Conditional result was False
2025-09-24 00:21:03.293278 | 
2025-09-24 00:21:03.293442 | TASK [bindep : Look for other-requirements.txt]
2025-09-24 00:21:04.018263 | controller | ok
2025-09-24 00:21:04.032413 | 
2025-09-24 00:21:04.032571 | TASK [bindep : Define bindep_file fact]
2025-09-24 00:21:04.071009 | controller | skipping: Conditional result was False
2025-09-24 00:21:04.085083 | 
2025-09-24 00:21:04.085249 | TASK [bindep : Look for bindep fallback file]
2025-09-24 00:21:04.123254 | controller | skipping: Conditional result was False
2025-09-24 00:21:04.137435 | 
2025-09-24 00:21:04.137599 | TASK [bindep : Define bindep_file fact]
2025-09-24 00:21:04.167036 | controller | skipping: Conditional result was False
2025-09-24 00:21:04.181671 | 
2025-09-24 00:21:04.181865 | TASK [bindep : Include bindep tasks]
2025-09-24 00:21:04.211326 | controller | skipping: Conditional result was False
2025-09-24 00:21:04.226401 | 
2025-09-24 00:21:04.226627 | TASK [bindep : Include install tasks]
2025-09-24 00:21:04.254827 | controller | skipping: Conditional result was False
2025-09-24 00:21:04.270183 | 
2025-09-24 00:21:04.270369 | LOOP [bindep : Include package tasks]
2025-09-24 00:21:04.367404 | 
2025-09-24 00:21:04.367915 | TASK [Run test-setup role]
2025-09-24 00:21:04.394214 | controller | ok
2025-09-24 00:21:04.421195 | 
2025-09-24 00:21:04.421346 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-09-24 00:21:05.199186 | controller | ok
2025-09-24 00:21:05.214127 | 
2025-09-24 00:21:05.214358 | TASK [test-setup : Run tools/test-setup.sh]
2025-09-24 00:21:05.591424 | controller | skipping: Conditional result was False
2025-09-24 00:21:05.646532 | 
2025-09-24 00:21:05.646770 | PLAY RECAP
2025-09-24 00:21:05.646843 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-24 00:21:05.646873 | 
2025-09-24 00:21:05.828530 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-09-24 00:21:05.829968 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-24 00:21:06.492729 | 
2025-09-24 00:21:06.492924 | PLAY [controller]
2025-09-24 00:21:06.515808 | 
2025-09-24 00:21:06.515992 | TASK [Create the /root directory]
2025-09-24 00:21:07.780188 | controller | ok
2025-09-24 00:21:07.795885 | 
2025-09-24 00:21:07.796239 | TASK [Install glibc-langpack-en]
2025-09-24 00:21:16.812130 | controller | ok: Nothing to do
2025-09-24 00:21:16.821481 | 
2025-09-24 00:21:16.821587 | TASK [Ensure controller directory exists]
2025-09-24 00:21:17.680032 | controller | changed
2025-09-24 00:21:17.687899 | 
2025-09-24 00:21:17.688000 | TASK [Install container runtime]
2025-09-24 00:21:17.773106 | controller | ok
2025-09-24 00:21:17.818951 | 
2025-09-24 00:21:17.819107 | LOOP [ensure-podman : Find distribution installation]
2025-09-24 00:21:17.858105 | controller | ok: "/var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-09-24 00:21:17.874429 | controller | included: /var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-09-24 00:21:17.881077 | 
2025-09-24 00:21:17.881144 | TASK [ensure-podman : Install podman (RedHat)]
2025-09-24 00:23:20.136200 | controller | changed
2025-09-24 00:23:20.153043 | 
2025-09-24 00:23:20.153189 | TASK [ensure-podman : Fetch podman version]
2025-09-24 00:23:21.371427 | controller | Client:       Podman Engine
2025-09-24 00:23:21.412836 | controller | Version:      4.6.2
2025-09-24 00:23:21.412901 | controller | API Version:  4.6.2
2025-09-24 00:23:21.412911 | controller | Go Version:   go1.19.12
2025-09-24 00:23:21.412930 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-09-24 00:23:21.412939 | controller | OS/Arch:      linux/amd64
2025-09-24 00:23:22.032830 | controller | ok: Runtime: 0:00:00.306125
2025-09-24 00:23:22.048968 | 
2025-09-24 00:23:22.049225 | TASK [ensure-podman : Print podman version installed]
2025-09-24 00:23:22.102927 | Podman version: Client:       Podman Engine
2025-09-24 00:23:22.103421 | Version:      4.6.2
2025-09-24 00:23:22.103500 | API Version:  4.6.2
2025-09-24 00:23:22.103547 | Go Version:   go1.19.12
2025-09-24 00:23:22.103590 | Built:        Mon Aug 28 19:38:31 2023
2025-09-24 00:23:22.103635 | OS/Arch:      linux/amd64
2025-09-24 00:23:22.117762 | 
2025-09-24 00:23:22.118052 | TASK [ensure-podman : Validate podman engine]
2025-09-24 00:23:22.487537 | controller | skipping: Conditional result was False
2025-09-24 00:23:22.499060 | 
2025-09-24 00:23:22.499187 | TASK [ensure-podman : Set up docker compatability socket]
2025-09-24 00:23:22.526153 | controller | skipping: Conditional result was False
2025-09-24 00:23:22.543564 | 
2025-09-24 00:23:22.543807 | TASK [Ensure python3.8 is present]
2025-09-24 00:23:22.569313 | controller | skipping: Conditional result was False
2025-09-24 00:23:22.576416 | 
2025-09-24 00:23:22.576494 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-09-24 00:23:22.598230 | controller | ok
2025-09-24 00:23:22.625407 | 
2025-09-24 00:23:22.625592 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-09-24 00:23:26.142891 | controller | ok: Nothing to do
2025-09-24 00:23:26.150768 | 
2025-09-24 00:23:26.150918 | TASK [our-ensure-python : Also install python3-devel]
2025-09-24 00:23:42.328219 | controller | changed
2025-09-24 00:23:42.343733 | 
2025-09-24 00:23:42.343846 | TASK [Run ensure-virtualenv role]
2025-09-24 00:23:42.376003 | controller | ok
2025-09-24 00:23:42.411530 | 
2025-09-24 00:23:42.411720 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-09-24 00:23:43.210157 | controller | /usr/bin/virtualenv
2025-09-24 00:23:43.812323 | controller | ok: Runtime: 0:00:00.008095
2025-09-24 00:23:43.827237 | 
2025-09-24 00:23:43.827387 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-09-24 00:23:43.866225 | controller | skipping: Conditional result was False
2025-09-24 00:23:43.866848 | controller | ok: All items complete
2025-09-24 00:23:43.866912 | 
2025-09-24 00:23:43.891137 | 
2025-09-24 00:23:43.891358 | TASK [Find the full path of the Python interpreter]
2025-09-24 00:23:44.697397 | controller | /usr/bin/python3
2025-09-24 00:23:45.257721 | controller | ok
2025-09-24 00:23:45.266182 | 
2025-09-24 00:23:45.266279 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-09-24 00:23:46.989618 | controller | created virtual environment CPython3.11.0.final.0-64 in 856ms
2025-09-24 00:23:47.083053 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-09-24 00:23:47.085479 | 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-09-24 00:23:47.085496 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-09-24 00:23:47.085515 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-09-24 00:23:47.629915 | controller | changed
2025-09-24 00:23:47.645324 | 
2025-09-24 00:23:47.645509 | TASK [Set selinux package]
2025-09-24 00:23:47.685753 | controller | ok
2025-09-24 00:23:47.693360 | 
2025-09-24 00:23:47.693447 | TASK [Set selinux package (Fedora)]
2025-09-24 00:23:47.728720 | controller | ok
2025-09-24 00:23:47.735492 | 
2025-09-24 00:23:47.735572 | TASK [Install selinux into virtualenv]
2025-09-24 00:23:50.868522 | controller | Collecting selinux-please-lie-to-me
2025-09-24 00:23:51.223192 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-09-24 00:23:51.814219 | controller | Collecting setuptools<50.0.0
2025-09-24 00:23:51.822443 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-09-24 00:23:51.892537 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 12.1 MB/s eta 0:00:00
2025-09-24 00:23:52.033112 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-09-24 00:23:52.033463 | controller |   Attempting uninstall: setuptools
2025-09-24 00:23:52.037040 | controller |     Found existing installation: setuptools 62.6.0
2025-09-24 00:23:52.151783 | controller |     Uninstalling setuptools-62.6.0:
2025-09-24 00:23:52.165244 | controller |       Successfully uninstalled setuptools-62.6.0
2025-09-24 00:23:53.015115 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-09-24 00:23:53.229142 | controller |
2025-09-24 00:23:53.495647 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-24 00:23:53.495706 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-24 00:23:53.625592 | controller | ok: Runtime: 0:00:04.933934
2025-09-24 00:23:53.638187 | 
2025-09-24 00:23:53.638334 | TASK [Install pytest-forked into virtualenv]
2025-09-24 00:23:55.161887 | controller | Collecting pytest-forked
2025-09-24 00:23:55.232879 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-09-24 00:23:55.309863 | controller | Collecting py
2025-09-24 00:23:55.316924 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-09-24 00:23:55.358665 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.4 MB/s eta 0:00:00
2025-09-24 00:23:55.579171 | controller | Collecting pytest>=3.10
2025-09-24 00:23:55.590600 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-09-24 00:23:55.609745 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 23.2 MB/s eta 0:00:00
2025-09-24 00:23:55.682385 | controller | Collecting iniconfig>=1
2025-09-24 00:23:55.690103 | controller |   Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB)
2025-09-24 00:23:55.770352 | controller | Collecting packaging>=20
2025-09-24 00:23:55.776120 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-09-24 00:23:55.793041 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.8 MB/s eta 0:00:00
2025-09-24 00:23:55.848246 | controller | Collecting pluggy<2,>=1.5
2025-09-24 00:23:55.853949 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-09-24 00:23:55.946646 | controller | Collecting pygments>=2.7.2
2025-09-24 00:23:55.951789 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-09-24 00:23:55.983734 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 54.6 MB/s eta 0:00:00
2025-09-24 00:23:56.109601 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-09-24 00:23:59.125931 | 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-24 00:23:59.153786 | controller |
2025-09-24 00:23:59.420303 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2
2025-09-24 00:23:59.420358 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-09-24 00:24:00.027555 | controller | ok: Runtime: 0:00:04.976443
2025-09-24 00:24:00.045371 | 
2025-09-24 00:24:00.045563 | TASK [Update pip]
2025-09-24 00:24:01.446809 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-09-24 00:24:01.711438 | controller | Collecting pip
2025-09-24 00:24:01.780010 | controller |   Downloading pip-25.2-py3-none-any.whl (1.8 MB)
2025-09-24 00:24:01.851671 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 26.3 MB/s eta 0:00:00
2025-09-24 00:24:01.987008 | controller | Installing collected packages: pip
2025-09-24 00:24:01.987404 | controller |   Attempting uninstall: pip
2025-09-24 00:24:01.991928 | controller |     Found existing installation: pip 22.2.2
2025-09-24 00:24:02.261146 | controller |     Uninstalling pip-22.2.2:
2025-09-24 00:24:02.294199 | controller |       Successfully uninstalled pip-22.2.2
2025-09-24 00:24:04.334246 | controller | Successfully installed pip-25.2
2025-09-24 00:24:04.946260 | controller | ok: Runtime: 0:00:03.738309
2025-09-24 00:24:04.953899 | 
2025-09-24 00:24:04.953986 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-09-24 00:24:05.830622 | controller | changed
2025-09-24 00:24:05.836721 | 
2025-09-24 00:24:05.836795 | TASK [Install ansible into virtualenv]
2025-09-24 00:24:07.197092 | controller | Processing ./src/github.com/ansible/ansible
2025-09-24 00:24:07.203715 | controller |   Installing build dependencies: started
2025-09-24 00:24:09.236862 | controller |   Installing build dependencies: finished with status 'done'
2025-09-24 00:24:10.799276 | controller |   Getting requirements to build wheel: started
2025-09-24 00:24:10.799353 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-09-24 00:24:11.761359 | controller |   Preparing metadata (pyproject.toml): started
2025-09-24 00:24:11.761425 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-09-24 00:24:11.764599 | 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-24 00:24:11.764637 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-09-24 00:24:12.217907 | controller | ERROR
2025-09-24 00:24:12.218296 | controller | {
2025-09-24 00:24:12.218364 | controller |   "delta": "0:00:05.378609",
2025-09-24 00:24:12.218409 | controller |   "end": "2025-09-24 00:24:11.946657",
2025-09-24 00:24:12.218450 | controller |   "msg": "non-zero return code",
2025-09-24 00:24:12.218514 | controller |   "rc": 1,
2025-09-24 00:24:12.218554 | controller |   "start": "2025-09-24 00:24:06.568048"
2025-09-24 00:24:12.218591 | controller | }
failure
2025-09-24 00:24:12.221782 | 
2025-09-24 00:24:12.221888 | PLAY RECAP
2025-09-24 00:24:12.221979 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-09-24 00:24:12.222025 | 
2025-09-24 00:24:12.408886 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-09-24 00:24:12.410083 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-24 00:24:13.051803 | 
2025-09-24 00:24:13.052000 | PLAY [all]
2025-09-24 00:24:13.073485 | 
2025-09-24 00:24:13.073593 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-09-24 00:24:14.939867 | controller | changed: non-zero return code
2025-09-24 00:24:14.954600 | 
2025-09-24 00:24:14.954868 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-09-24 00:24:14.986400 | controller | skipping: Conditional result was False
2025-09-24 00:24:15.001226 | 
2025-09-24 00:24:15.001392 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-09-24 00:24:15.047755 | 
2025-09-24 00:24:15.048075 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-09-24 00:24:15.093886 | 
2025-09-24 00:24:15.094256 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-09-24 00:24:15.125718 | controller | skipping: Conditional result was False
2025-09-24 00:24:15.135889 | 
2025-09-24 00:24:15.136037 | LOOP [fetch-subunit-output : Generate subunit file]
2025-09-24 00:24:15.172766 | 
2025-09-24 00:24:15.172971 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-09-24 00:24:15.200134 | controller | skipping: Conditional result was False
2025-09-24 00:24:15.209870 | 
2025-09-24 00:24:15.209999 | TASK [fetch-subunit-output : Remove the temporary file]
2025-09-24 00:24:15.236732 | controller | skipping: Conditional result was False
2025-09-24 00:24:15.246934 | 
2025-09-24 00:24:15.247099 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-09-24 00:24:15.275316 | controller | skipping: Conditional result was False
2025-09-24 00:24:15.319855 | 
2025-09-24 00:24:15.319952 | PLAY RECAP
2025-09-24 00:24:15.320013 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-09-24 00:24:15.320040 | 
2025-09-24 00:24:15.450561 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-09-24 00:24:15.451563 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-09-24 00:24:16.113753 | 
2025-09-24 00:24:16.113969 | PLAY [all:!appliance*]
2025-09-24 00:24:16.137560 | 
2025-09-24 00:24:16.137760 | TASK [unregister the node]
2025-09-24 00:24:16.494798 | controller | skipping: Conditional result was False
2025-09-24 00:24:16.509588 | 
2025-09-24 00:24:16.509811 | TASK [include_role : fetch-output]
2025-09-24 00:24:16.571890 | controller | ok
2025-09-24 00:24:16.611383 | 
2025-09-24 00:24:16.611533 | TASK [fetch-output : Set log path for multiple nodes]
2025-09-24 00:24:16.689887 | controller | skipping: Conditional result was False
2025-09-24 00:24:16.705522 | 
2025-09-24 00:24:16.705754 | TASK [fetch-output : Set log path for single node]
2025-09-24 00:24:16.771200 | controller | ok
2025-09-24 00:24:16.785642 | 
2025-09-24 00:24:16.785856 | LOOP [fetch-output : Ensure local output dirs]
2025-09-24 00:24:17.272837 | controller -> localhost | ok: "/var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/work/logs"
2025-09-24 00:24:17.552225 | controller -> localhost | changed: "/var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/work/artifacts"
2025-09-24 00:24:17.811234 | controller -> localhost | changed: "/var/lib/zuul/builds/2f9c844e26964be0a631155d61cf4cf9/work/docs"
2025-09-24 00:24:17.826361 | 
2025-09-24 00:24:17.826493 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-09-24 00:24:20.090637 | controller | changed:
2025-09-24 00:24:20.091283 | controller | .d..t...... ./
2025-09-24 00:24:20.091340 | controller | cd+++++++++ controller/
2025-09-24 00:24:20.091395 | controller | changed: All items complete
2025-09-24 00:24:20.091427 | 
2025-09-24 00:24:22.184799 | controller | changed: .d..t...... ./
2025-09-24 00:24:24.234277 | controller | changed: .d..t...... ./
2025-09-24 00:24:24.255076 | 
2025-09-24 00:24:24.255267 | TASK [include_role : fetch-output-openshift]
2025-09-24 00:24:24.283689 | controller | skipping: Conditional result was False
2025-09-24 00:24:24.294006 | 
2025-09-24 00:24:24.294659 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-09-24 00:24:24.333387 | controller | skipping: Conditional result was False
2025-09-24 00:24:24.344273 | controller | skipping: Conditional result was False
2025-09-24 00:24:24.382032 | 
2025-09-24 00:24:24.382195 | PLAY [localhost]
2025-09-24 00:24:24.397199 | 
2025-09-24 00:24:24.397341 | TASK [Run Zuul manifest role]
2025-09-24 00:24:24.428289 | localhost | ok
2025-09-24 00:24:24.443106 | 
2025-09-24 00:24:24.443241 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-09-24 00:24:24.861874 | localhost | changed
2025-09-24 00:24:24.867071 | 
2025-09-24 00:24:24.867134 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-09-24 00:24:24.897603 | localhost | ok
2025-09-24 00:24:24.906606 | 
2025-09-24 00:24:24.906666 | TASK [Set zuul-log-path fact]
2025-09-24 00:24:24.963096 | localhost | ok
2025-09-24 00:24:24.976699 | 
2025-09-24 00:24:24.976769 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-09-24 00:24:25.016014 | localhost | ok
2025-09-24 00:24:25.023995 | 
2025-09-24 00:24:25.024055 | LOOP [Run upload-logs-swift role]
2025-09-24 00:24:25.073805 | localhost | Output suppressed because no_log was given
2025-09-24 00:24:25.116465 | 
2025-09-24 00:24:25.116626 | TASK [Set zuul-log-path fact]
2025-09-24 00:24:25.154426 | localhost | skipping: Conditional result was False
2025-09-24 00:24:25.160958 | 
2025-09-24 00:24:25.161032 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-09-24 00:24:25.607832 | localhost -> localhost | ok: Runtime: 0:00:00.007534
2025-09-24 00:24:25.621021 | 
2025-09-24 00:24:25.621189 | TASK [upload-logs-swift : Upload logs to swift]