2025-11-20 00:26:00.484483 | Job console starting...
2025-11-20 00:26:00.494231 | Updating repositories
2025-11-20 00:26:00.622262 | Preparing job workspace
2025-11-20 00:26:04.357334 | Running Ansible setup...
2025-11-20 00:26:09.382957 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-20 00:26:10.034364 | 
2025-11-20 00:26:10.034505 | PLAY [localhost]
2025-11-20 00:26:10.043199 | 
2025-11-20 00:26:10.043308 | TASK [Gathering Facts]
2025-11-20 00:26:11.186856 | localhost | ok
2025-11-20 00:26:11.209619 | 
2025-11-20 00:26:11.209769 | TASK [Setup log path fact]
2025-11-20 00:26:11.231124 | localhost | ok
2025-11-20 00:26:11.250216 | 
2025-11-20 00:26:11.250336 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-20 00:26:11.281687 | localhost | ok
2025-11-20 00:26:11.292175 | 
2025-11-20 00:26:11.292428 | TASK [emit-job-header : Print job information]
2025-11-20 00:26:11.322903 | # Job Information
2025-11-20 00:26:11.323075 | Ansible Version: 2.15.12
2025-11-20 00:26:11.323110 | Job: ansible-test-sanity-docker-devel
2025-11-20 00:26:11.323133 | Pipeline: periodic
2025-11-20 00:26:11.323153 | Executor: ze01.softwarefactory-project.io
2025-11-20 00:26:11.323172 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-20 00:26:11.323195 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/6e3/ansible/6e39ad2965fb4c3b8b6498089679a9b1/
2025-11-20 00:26:11.323215 | Event ID: 4015b71040db4124b5e62c0aaaa553e0
2025-11-20 00:26:11.328406 | 
2025-11-20 00:26:11.328510 | LOOP [emit-job-header : Print node information]
2025-11-20 00:26:11.441664 | localhost | ok:
2025-11-20 00:26:11.442003 | localhost | # Node Information
2025-11-20 00:26:11.442074 | localhost | Inventory Hostname: controller
2025-11-20 00:26:11.442104 | localhost | Hostname: np0005528762
2025-11-20 00:26:11.442130 | localhost | Username: zuul
2025-11-20 00:26:11.442163 | localhost | Distro: Fedora 37
2025-11-20 00:26:11.442188 | localhost | Provider: ansible-vexxhost-ca-ymq-1
2025-11-20 00:26:11.442211 | localhost | Region: ca-ymq-1
2025-11-20 00:26:11.442232 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-20 00:26:11.442254 | localhost | Product Name: OpenStack Nova
2025-11-20 00:26:11.442276 | localhost | Interface IP: 162.253.55.227
2025-11-20 00:26:11.467984 | 
2025-11-20 00:26:11.468127 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-20 00:26:11.936425 | localhost -> localhost | changed
2025-11-20 00:26:11.944867 | 
2025-11-20 00:26:11.944993 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-20 00:26:12.935744 | localhost -> localhost | changed
2025-11-20 00:26:12.969485 | 
2025-11-20 00:26:12.969581 | PLAY [all:!appliance*]
2025-11-20 00:26:13.000314 | 
2025-11-20 00:26:13.000448 | TASK [include_role : start-zuul-console]
2025-11-20 00:26:13.027264 | controller | ok
2025-11-20 00:26:13.049089 | 
2025-11-20 00:26:13.049209 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-20 00:26:13.470842 | controller | ok
2025-11-20 00:26:13.491497 | 
2025-11-20 00:26:13.491632 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-20 00:26:47.641529 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-20 00:26:47.654884 | 
2025-11-20 00:26:47.655043 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-20 00:26:48.208007 | controller | skipping: Conditional result was False
2025-11-20 00:26:48.224555 | 
2025-11-20 00:26:48.225640 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-20 00:26:48.242828 | controller | skipping: Conditional result was False
2025-11-20 00:26:48.254066 | 
2025-11-20 00:26:48.254685 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-20 00:26:48.280859 | controller | skipping: Conditional result was False
2025-11-20 00:26:48.293358 | 
2025-11-20 00:26:48.293509 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-20 00:26:48.320402 | controller | skipping: Conditional result was False
2025-11-20 00:26:48.333085 | 
2025-11-20 00:26:48.333250 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-20 00:26:48.357987 | controller | skipping: Conditional result was False
2025-11-20 00:26:48.365848 | 
2025-11-20 00:26:48.365972 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-20 00:26:48.402281 | controller | skipping: Conditional result was False
2025-11-20 00:26:48.417121 | 
2025-11-20 00:26:48.417237 | TASK [Disable Fedora Modular]
2025-11-20 00:26:48.771632 | controller | changed
2025-11-20 00:26:48.782371 | 
2025-11-20 00:26:48.782510 | TASK [Enable EPEL]
2025-11-20 00:26:48.801329 | controller | skipping: Conditional result was False
2025-11-20 00:26:48.813147 | 
2025-11-20 00:26:48.813318 | TASK [Register the RHEL node]
2025-11-20 00:26:49.385968 | 
2025-11-20 00:26:49.386150 | TASK [Show the subscription-manager status]
2025-11-20 00:26:49.944737 | controller | skipping: Conditional result was False
2025-11-20 00:26:49.954731 | 
2025-11-20 00:26:49.954853 | TASK [Enable EPEL on RHEL]
2025-11-20 00:26:50.047870 | controller | skipping: Conditional result was False
2025-11-20 00:26:50.056952 | 
2025-11-20 00:26:50.057101 | TASK [Install git and tox]
2025-11-20 00:27:42.200385 | controller | changed
2025-11-20 00:27:42.206872 | 
2025-11-20 00:27:42.206961 | TASK [include_role : prepare-workspace]
2025-11-20 00:27:42.226584 | controller | ok
2025-11-20 00:27:42.248608 | 
2025-11-20 00:27:42.248738 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-20 00:27:42.497102 | controller | ok
2025-11-20 00:27:42.507645 | 
2025-11-20 00:27:42.507810 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-20 00:27:55.222116 | controller | Output suppressed because no_log was given
2025-11-20 00:27:55.279441 | 
2025-11-20 00:27:55.279570 | TASK [include_role : prepare-workspace-openshift]
2025-11-20 00:27:55.297119 | controller | skipping: Conditional result was False
2025-11-20 00:27:55.326793 | 
2025-11-20 00:27:55.326898 | PLAY [all:!appliance]
2025-11-20 00:27:55.348094 | 
2025-11-20 00:27:55.348215 | TASK [Run add-build-sshkey role (RSA)]
2025-11-20 00:27:55.370843 | controller | ok
2025-11-20 00:27:55.390997 | 
2025-11-20 00:27:55.391133 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-20 00:27:55.630232 | controller -> localhost | ok
2025-11-20 00:27:55.639563 | 
2025-11-20 00:27:55.639689 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-20 00:27:55.666399 | controller | ok
2025-11-20 00:27:55.691694 | controller | included: /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-20 00:27:55.699410 | 
2025-11-20 00:27:55.699510 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-20 00:27:56.143240 | controller -> localhost | Generating public/private rsa key pair.
2025-11-20 00:27:56.143537 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/work/6e39ad2965fb4c3b8b6498089679a9b1_id_rsa.
2025-11-20 00:27:56.143600 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/work/6e39ad2965fb4c3b8b6498089679a9b1_id_rsa.pub.
2025-11-20 00:27:56.143634 | controller -> localhost | The key fingerprint is:
2025-11-20 00:27:56.143667 | controller -> localhost | SHA256:uo1diYv2UAl8vAaKWCkGLaXmg3y2vSBUAMnNMyQZOSA zuul-build-sshkey
2025-11-20 00:27:56.143689 | controller -> localhost | The key's randomart image is:
2025-11-20 00:27:56.143709 | controller -> localhost | +---[RSA 2048]----+
2025-11-20 00:27:56.143727 | controller -> localhost | |EBO.             |
2025-11-20 00:27:56.143746 | controller -> localhost | |=*+* . .         |
2025-11-20 00:27:56.143763 | controller -> localhost | |o++.o + o        |
2025-11-20 00:27:56.143781 | controller -> localhost | |*+.. . + o       |
2025-11-20 00:27:56.143798 | controller -> localhost | |o=.o.   S        |
2025-11-20 00:27:56.143846 | controller -> localhost | |. + o  + . .     |
2025-11-20 00:27:56.143873 | controller -> localhost | | . o .o . o      |
2025-11-20 00:27:56.143892 | controller -> localhost | |  . . oB o       |
2025-11-20 00:27:56.143909 | controller -> localhost | |     o+.=        |
2025-11-20 00:27:56.143929 | controller -> localhost | +----[SHA256]-----+
2025-11-20 00:27:56.143979 | controller -> localhost | ok: Runtime: 0:00:00.034473
2025-11-20 00:27:56.154267 | 
2025-11-20 00:27:56.154398 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-20 00:27:56.189835 | controller | ok
2025-11-20 00:27:56.203610 | controller | included: /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-20 00:27:56.215937 | 
2025-11-20 00:27:56.216079 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-20 00:27:56.232769 | controller | skipping: Conditional result was False
2025-11-20 00:27:56.242248 | 
2025-11-20 00:27:56.242374 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-20 00:27:56.673399 | controller | changed
2025-11-20 00:27:56.681914 | 
2025-11-20 00:27:56.682048 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-20 00:27:56.894455 | controller | ok
2025-11-20 00:27:56.905070 | 
2025-11-20 00:27:56.905176 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-20 00:27:57.553957 | controller | changed
2025-11-20 00:27:57.565223 | 
2025-11-20 00:27:57.565375 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-20 00:27:58.199175 | controller | changed
2025-11-20 00:27:58.214674 | 
2025-11-20 00:27:58.214910 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-20 00:27:58.242476 | controller | skipping: Conditional result was False
2025-11-20 00:27:58.251973 | 
2025-11-20 00:27:58.252115 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-20 00:27:58.710365 | controller -> localhost | changed
2025-11-20 00:27:58.729840 | 
2025-11-20 00:27:58.729992 | TASK [add-build-sshkey : Add back temp key]
2025-11-20 00:27:59.002368 | controller -> localhost | Identity added: /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/work/6e39ad2965fb4c3b8b6498089679a9b1_id_rsa (zuul-build-sshkey)
2025-11-20 00:27:59.002744 | controller -> localhost | ok: Runtime: 0:00:00.010027
2025-11-20 00:27:59.024734 | 
2025-11-20 00:27:59.025050 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-20 00:27:59.443077 | controller | ok
2025-11-20 00:27:59.452901 | 
2025-11-20 00:27:59.453038 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-20 00:27:59.479681 | controller | skipping: Conditional result was False
2025-11-20 00:27:59.500801 | 
2025-11-20 00:27:59.500959 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-20 00:27:59.528854 | controller | ok
2025-11-20 00:27:59.556885 | 
2025-11-20 00:27:59.557048 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-20 00:27:59.785907 | controller -> localhost | ok
2025-11-20 00:27:59.793199 | 
2025-11-20 00:27:59.793316 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-20 00:27:59.823701 | controller | ok
2025-11-20 00:27:59.835313 | controller | included: /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-20 00:27:59.841417 | 
2025-11-20 00:27:59.841480 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-20 00:28:00.131365 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-20 00:28:00.131604 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/work/6e39ad2965fb4c3b8b6498089679a9b1_id_ecdsa.
2025-11-20 00:28:00.131680 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/work/6e39ad2965fb4c3b8b6498089679a9b1_id_ecdsa.pub.
2025-11-20 00:28:00.131727 | controller -> localhost | The key fingerprint is:
2025-11-20 00:28:00.131754 | controller -> localhost | SHA256:vhQJAY6SJApm3MTAbRIZ51tXjLEc+OL0EKhZ+rTzzQs zuul-build-sshkey
2025-11-20 00:28:00.131779 | controller -> localhost | The key's randomart image is:
2025-11-20 00:28:00.131804 | controller -> localhost | +---[ECDSA 521]---+
2025-11-20 00:28:00.131828 | controller -> localhost | |=BXoo.oo+.       |
2025-11-20 00:28:00.131851 | controller -> localhost | |B*oX o.o+.       |
2025-11-20 00:28:00.131873 | controller -> localhost | |+ O...++         |
2025-11-20 00:28:00.131896 | controller -> localhost | | = .o+.o .       |
2025-11-20 00:28:00.131918 | controller -> localhost | |  o.+ + S        |
2025-11-20 00:28:00.131941 | controller -> localhost | |   + . o .       |
2025-11-20 00:28:00.131967 | controller -> localhost | |    oEo o        |
2025-11-20 00:28:00.131990 | controller -> localhost | |     ..+ .       |
2025-11-20 00:28:00.132031 | controller -> localhost | |       .o        |
2025-11-20 00:28:00.132062 | controller -> localhost | +----[SHA256]-----+
2025-11-20 00:28:00.132127 | controller -> localhost | ok: Runtime: 0:00:00.007395
2025-11-20 00:28:00.141585 | 
2025-11-20 00:28:00.141679 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-20 00:28:00.171427 | controller | ok
2025-11-20 00:28:00.187622 | controller | included: /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-20 00:28:00.205715 | 
2025-11-20 00:28:00.205863 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-20 00:28:00.232138 | controller | skipping: Conditional result was False
2025-11-20 00:28:00.243784 | 
2025-11-20 00:28:00.243932 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-20 00:28:00.503963 | controller | changed
2025-11-20 00:28:00.521671 | 
2025-11-20 00:28:00.521880 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-20 00:28:00.741642 | controller | ok
2025-11-20 00:28:00.748760 | 
2025-11-20 00:28:00.748865 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-20 00:28:01.365702 | controller | changed
2025-11-20 00:28:01.374722 | 
2025-11-20 00:28:01.374878 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-20 00:28:02.004091 | controller | changed
2025-11-20 00:28:02.018508 | 
2025-11-20 00:28:02.018661 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-20 00:28:02.043733 | controller | skipping: Conditional result was False
2025-11-20 00:28:02.102645 | 
2025-11-20 00:28:02.102906 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-20 00:28:02.383441 | controller -> localhost | changed
2025-11-20 00:28:02.404364 | 
2025-11-20 00:28:02.404509 | TASK [add-build-sshkey : Add back temp key]
2025-11-20 00:28:02.706269 | controller -> localhost | Identity added: /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/work/6e39ad2965fb4c3b8b6498089679a9b1_id_ecdsa (zuul-build-sshkey)
2025-11-20 00:28:02.706483 | controller -> localhost | ok: Runtime: 0:00:00.009619
2025-11-20 00:28:02.713544 | 
2025-11-20 00:28:02.713640 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-20 00:28:02.918700 | controller | ok
2025-11-20 00:28:02.936081 | 
2025-11-20 00:28:02.936440 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-20 00:28:02.963489 | controller | skipping: Conditional result was False
2025-11-20 00:28:02.976794 | 
2025-11-20 00:28:02.976916 | TASK [include_role : remove-zuul-sshkey]
2025-11-20 00:28:03.000908 | controller | skipping: Conditional result was False
2025-11-20 00:28:03.008846 | 
2025-11-20 00:28:03.008953 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-20 00:28:03.254062 | controller | ok: "logs"
2025-11-20 00:28:03.254500 | controller | ok: All items complete
2025-11-20 00:28:03.254574 | 
2025-11-20 00:28:03.468603 | controller | ok: "artifacts"
2025-11-20 00:28:03.658905 | controller | ok: "docs"
2025-11-20 00:28:03.677304 | 
2025-11-20 00:28:03.677521 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-20 00:28:03.934938 | controller | changed: "logs"
2025-11-20 00:28:04.153981 | controller | changed: "artifacts"
2025-11-20 00:28:04.359284 | controller | changed: "docs"
2025-11-20 00:28:04.436781 | 
2025-11-20 00:28:04.436915 | PLAY RECAP
2025-11-20 00:28:04.436979 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-20 00:28:04.437042 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-20 00:28:04.437077 | 
2025-11-20 00:28:04.608574 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-20 00:28:04.609716 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-20 00:28:05.312916 | 
2025-11-20 00:28:05.313099 | PLAY [all]
2025-11-20 00:28:05.348479 | 
2025-11-20 00:28:05.348644 | TASK [Install binary dependencies]
2025-11-20 00:28:05.411554 | controller | ok
2025-11-20 00:28:05.436197 | 
2025-11-20 00:28:05.436345 | TASK [bindep : Include find tasks]
2025-11-20 00:28:05.467786 | controller | ok
2025-11-20 00:28:05.477267 | controller | included: /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-20 00:28:05.484854 | 
2025-11-20 00:28:05.485256 | TASK [bindep : Look for bindep.txt]
2025-11-20 00:28:05.862351 | controller | ok
2025-11-20 00:28:05.870049 | 
2025-11-20 00:28:05.870163 | TASK [bindep : Define bindep_file fact]
2025-11-20 00:28:05.895568 | controller | skipping: Conditional result was False
2025-11-20 00:28:05.903091 | 
2025-11-20 00:28:05.903224 | TASK [bindep : Look for other-requirements.txt]
2025-11-20 00:28:06.123431 | controller | ok
2025-11-20 00:28:06.133670 | 
2025-11-20 00:28:06.133806 | TASK [bindep : Define bindep_file fact]
2025-11-20 00:28:06.181963 | controller | skipping: Conditional result was False
2025-11-20 00:28:06.190707 | 
2025-11-20 00:28:06.190835 | TASK [bindep : Look for bindep fallback file]
2025-11-20 00:28:06.231307 | controller | skipping: Conditional result was False
2025-11-20 00:28:06.241645 | 
2025-11-20 00:28:06.241802 | TASK [bindep : Define bindep_file fact]
2025-11-20 00:28:06.277725 | controller | skipping: Conditional result was False
2025-11-20 00:28:06.293948 | 
2025-11-20 00:28:06.294162 | TASK [bindep : Include bindep tasks]
2025-11-20 00:28:06.331415 | controller | skipping: Conditional result was False
2025-11-20 00:28:06.342528 | 
2025-11-20 00:28:06.342668 | TASK [bindep : Include install tasks]
2025-11-20 00:28:06.379335 | controller | skipping: Conditional result was False
2025-11-20 00:28:06.389834 | 
2025-11-20 00:28:06.389968 | LOOP [bindep : Include package tasks]
2025-11-20 00:28:06.470166 | 
2025-11-20 00:28:06.470776 | TASK [Run test-setup role]
2025-11-20 00:28:06.495546 | controller | ok
2025-11-20 00:28:06.524371 | 
2025-11-20 00:28:06.524497 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-20 00:28:06.772326 | controller | ok
2025-11-20 00:28:06.783818 | 
2025-11-20 00:28:06.783939 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-20 00:28:07.325546 | controller | skipping: Conditional result was False
2025-11-20 00:28:07.356125 | 
2025-11-20 00:28:07.356226 | PLAY RECAP
2025-11-20 00:28:07.356265 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-20 00:28:07.356286 | 
2025-11-20 00:28:07.491042 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-20 00:28:07.492030 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-20 00:28:08.147597 | 
2025-11-20 00:28:08.147723 | PLAY [controller]
2025-11-20 00:28:08.168405 | 
2025-11-20 00:28:08.168536 | TASK [Create the /root directory]
2025-11-20 00:28:08.603946 | controller | ok
2025-11-20 00:28:08.627944 | 
2025-11-20 00:28:08.628141 | TASK [Install glibc-langpack-en]
2025-11-20 00:28:12.783691 | controller | ok: Nothing to do
2025-11-20 00:28:12.795447 | 
2025-11-20 00:28:12.795576 | TASK [Ensure controller directory exists]
2025-11-20 00:28:13.011580 | controller | changed
2025-11-20 00:28:13.019219 | 
2025-11-20 00:28:13.019478 | TASK [Install container runtime]
2025-11-20 00:28:13.092728 | controller | ok
2025-11-20 00:28:13.144176 | 
2025-11-20 00:28:13.144297 | LOOP [ensure-podman : Find distribution installation]
2025-11-20 00:28:13.186691 | controller | ok: "/var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-20 00:28:13.196681 | controller | included: /var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-20 00:28:13.204362 | 
2025-11-20 00:28:13.204489 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-20 00:29:36.705608 | controller | changed
2025-11-20 00:29:36.724035 | 
2025-11-20 00:29:36.724233 | TASK [ensure-podman : Fetch podman version]
2025-11-20 00:29:37.278073 | controller | Client:       Podman Engine
2025-11-20 00:29:37.278247 | controller | Version:      4.6.2
2025-11-20 00:29:37.278354 | controller | API Version:  4.6.2
2025-11-20 00:29:37.278431 | controller | Go Version:   go1.19.12
2025-11-20 00:29:37.278518 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-20 00:29:37.278618 | controller | OS/Arch:      linux/amd64
2025-11-20 00:29:37.771241 | controller | ok: Runtime: 0:00:00.180559
2025-11-20 00:29:37.787599 | 
2025-11-20 00:29:37.787838 | TASK [ensure-podman : Print podman version installed]
2025-11-20 00:29:37.830156 | Podman version: Client:       Podman Engine
2025-11-20 00:29:37.830454 | Version:      4.6.2
2025-11-20 00:29:37.830519 | API Version:  4.6.2
2025-11-20 00:29:37.830566 | Go Version:   go1.19.12
2025-11-20 00:29:37.830607 | Built:        Mon Aug 28 19:38:31 2023
2025-11-20 00:29:37.830649 | OS/Arch:      linux/amd64
2025-11-20 00:29:37.855813 | 
2025-11-20 00:29:37.855974 | TASK [ensure-podman : Validate podman engine]
2025-11-20 00:29:38.394572 | controller | skipping: Conditional result was False
2025-11-20 00:29:38.402010 | 
2025-11-20 00:29:38.402162 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-20 00:29:38.416084 | controller | skipping: Conditional result was False
2025-11-20 00:29:38.430553 | 
2025-11-20 00:29:38.430665 | TASK [Ensure python3.8 is present]
2025-11-20 00:29:38.455184 | controller | skipping: Conditional result was False
2025-11-20 00:29:38.463676 | 
2025-11-20 00:29:38.463814 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-20 00:29:38.486583 | controller | ok
2025-11-20 00:29:38.514309 | 
2025-11-20 00:29:38.514457 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-20 00:29:40.178376 | controller | ok: Nothing to do
2025-11-20 00:29:40.187995 | 
2025-11-20 00:29:40.188163 | TASK [our-ensure-python : Also install python3-devel]
2025-11-20 00:29:49.135127 | controller | changed
2025-11-20 00:29:49.161738 | 
2025-11-20 00:29:49.161892 | TASK [Run ensure-virtualenv role]
2025-11-20 00:29:49.189645 | controller | ok
2025-11-20 00:29:49.261001 | 
2025-11-20 00:29:49.261144 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-20 00:29:49.474191 | controller | /usr/bin/virtualenv
2025-11-20 00:29:49.795361 | controller | ok: Runtime: 0:00:00.005608
2025-11-20 00:29:49.803293 | 
2025-11-20 00:29:49.803420 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-20 00:29:49.847348 | controller | skipping: Conditional result was False
2025-11-20 00:29:49.847801 | controller | ok: All items complete
2025-11-20 00:29:49.847860 | 
2025-11-20 00:29:49.885843 | 
2025-11-20 00:29:49.886067 | TASK [Find the full path of the Python interpreter]
2025-11-20 00:29:50.138530 | controller | /usr/bin/python3
2025-11-20 00:29:50.438918 | controller | ok
2025-11-20 00:29:50.449227 | 
2025-11-20 00:29:50.449362 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-20 00:29:51.275836 | controller | created virtual environment CPython3.11.0.final.0-64 in 483ms
2025-11-20 00:29:51.294698 | controller |   creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-20 00:29:51.294734 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv)
2025-11-20 00:29:51.294745 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-20 00:29:51.294765 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-20 00:29:51.537903 | controller | changed
2025-11-20 00:29:51.552353 | 
2025-11-20 00:29:51.552535 | TASK [Set selinux package]
2025-11-20 00:29:51.599026 | controller | ok
2025-11-20 00:29:51.605874 | 
2025-11-20 00:29:51.606110 | TASK [Set selinux package (Fedora)]
2025-11-20 00:29:51.650094 | controller | ok
2025-11-20 00:29:51.655911 | 
2025-11-20 00:29:51.656004 | TASK [Install selinux into virtualenv]
2025-11-20 00:30:06.224031 | controller | Collecting selinux-please-lie-to-me
2025-11-20 00:30:17.467830 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-20 00:30:17.772191 | controller | Collecting setuptools<50.0.0
2025-11-20 00:30:17.878598 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-20 00:30:17.920582 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.6 MB/s eta 0:00:00
2025-11-20 00:30:18.003494 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-20 00:30:18.003711 | controller |   Attempting uninstall: setuptools
2025-11-20 00:30:18.006144 | controller |     Found existing installation: setuptools 62.6.0
2025-11-20 00:30:18.069449 | controller |     Uninstalling setuptools-62.6.0:
2025-11-20 00:30:18.077643 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-20 00:30:18.430493 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-20 00:30:29.857457 | controller |
2025-11-20 00:30:29.947883 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-20 00:30:29.947916 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-20 00:30:30.207828 | controller | ok: Runtime: 0:00:38.084644
2025-11-20 00:30:30.216923 | 
2025-11-20 00:30:30.217049 | TASK [Install pytest-forked into virtualenv]
2025-11-20 00:31:07.054581 | controller | Collecting pytest-forked
2025-11-20 00:31:19.300467 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-20 00:31:19.355078 | controller | Collecting py
2025-11-20 00:31:19.366287 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-20 00:31:19.382633 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 8.1 MB/s eta 0:00:00
2025-11-20 00:31:19.495003 | controller | Collecting pytest>=3.10
2025-11-20 00:31:19.498801 | controller |   Downloading pytest-9.0.1-py3-none-any.whl (373 kB)
2025-11-20 00:31:19.514060 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 30.7 MB/s eta 0:00:00
2025-11-20 00:31:19.554731 | controller | Collecting iniconfig>=1.0.1
2025-11-20 00:31:19.568177 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-20 00:31:19.615956 | controller | Collecting packaging>=22
2025-11-20 00:31:19.656316 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-20 00:31:19.664344 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 12.9 MB/s eta 0:00:00
2025-11-20 00:31:19.696914 | controller | Collecting pluggy<2,>=1.5
2025-11-20 00:31:19.702833 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-20 00:31:19.754796 | controller | Collecting pygments>=2.7.2
2025-11-20 00:31:19.762261 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-20 00:31:19.799954 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 34.5 MB/s eta 0:00:00
2025-11-20 00:31:19.872210 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-20 00:31:20.934931 | 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.1 pytest-forked-1.6.0
2025-11-20 00:31:20.944497 | controller |
2025-11-20 00:31:21.019186 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-20 00:31:21.019273 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-20 00:31:21.322592 | controller | ok: Runtime: 0:00:50.534601
2025-11-20 00:31:21.329615 | 
2025-11-20 00:31:21.329882 | TASK [Update pip]
2025-11-20 00:31:21.851879 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-20 00:31:34.339672 | controller | Collecting pip
2025-11-20 00:31:46.485802 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-20 00:31:46.532273 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 41.7 MB/s eta 0:00:00
2025-11-20 00:31:46.596017 | controller | Installing collected packages: pip
2025-11-20 00:31:46.596177 | controller |   Attempting uninstall: pip
2025-11-20 00:31:46.598330 | controller |     Found existing installation: pip 22.2.2
2025-11-20 00:31:46.735083 | controller |     Uninstalling pip-22.2.2:
2025-11-20 00:31:46.749917 | controller |       Successfully uninstalled pip-22.2.2
2025-11-20 00:31:47.541814 | controller | Successfully installed pip-25.3
2025-11-20 00:31:47.878139 | controller | ok: Runtime: 0:00:26.077172
2025-11-20 00:31:47.895747 | 
2025-11-20 00:31:47.895932 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-20 00:31:48.131344 | controller | changed
2025-11-20 00:31:48.146497 | 
2025-11-20 00:31:48.146680 | TASK [Install ansible into virtualenv]
2025-11-20 00:31:48.669166 | controller | Processing ./src/github.com/ansible/ansible
2025-11-20 00:31:48.672548 | controller |   Installing build dependencies: started
2025-11-20 00:32:45.454065 | controller |   Installing build dependencies: finished with status 'done'
2025-11-20 00:32:45.454609 | controller |   Getting requirements to build wheel: started
2025-11-20 00:32:46.264869 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-20 00:32:46.264939 | controller |   Preparing metadata (pyproject.toml): started
2025-11-20 00:32:46.780530 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-20 00:32:46.785333 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-11-20 00:32:46.788898 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-20 00:32:47.224777 | controller | ERROR
2025-11-20 00:32:47.225175 | controller | {
2025-11-20 00:32:47.225217 | controller |   "delta": "0:00:58.471534",
2025-11-20 00:32:47.225240 | controller |   "end": "2025-11-20 00:32:46.859637",
2025-11-20 00:32:47.225266 | controller |   "msg": "non-zero return code",
2025-11-20 00:32:47.225295 | controller |   "rc": 1,
2025-11-20 00:32:47.225313 | controller |   "start": "2025-11-20 00:31:48.388103"
2025-11-20 00:32:47.225329 | controller | }
failure
2025-11-20 00:32:47.227367 | 
2025-11-20 00:32:47.227423 | PLAY RECAP
2025-11-20 00:32:47.227466 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-20 00:32:47.227486 | 
2025-11-20 00:32:47.377740 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-20 00:32:47.379209 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-20 00:32:48.002932 | 
2025-11-20 00:32:48.003116 | PLAY [all]
2025-11-20 00:32:48.026616 | 
2025-11-20 00:32:48.026747 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-20 00:32:48.273632 | controller | changed: non-zero return code
2025-11-20 00:32:48.279407 | 
2025-11-20 00:32:48.279490 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-20 00:32:48.294432 | controller | skipping: Conditional result was False
2025-11-20 00:32:48.301844 | 
2025-11-20 00:32:48.301969 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-20 00:32:48.334099 | 
2025-11-20 00:32:48.334265 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-20 00:32:48.358388 | 
2025-11-20 00:32:48.358587 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-20 00:32:48.384341 | controller | skipping: Conditional result was False
2025-11-20 00:32:48.394945 | 
2025-11-20 00:32:48.395125 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-20 00:32:48.420816 | 
2025-11-20 00:32:48.421067 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-20 00:32:48.436792 | controller | skipping: Conditional result was False
2025-11-20 00:32:48.445615 | 
2025-11-20 00:32:48.445751 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-20 00:32:48.461250 | controller | skipping: Conditional result was False
2025-11-20 00:32:48.470545 | 
2025-11-20 00:32:48.470690 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-20 00:32:48.486539 | controller | skipping: Conditional result was False
2025-11-20 00:32:48.524290 | 
2025-11-20 00:32:48.524417 | PLAY RECAP
2025-11-20 00:32:48.524473 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-20 00:32:48.524503 | 
2025-11-20 00:32:48.642551 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-20 00:32:48.643384 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-20 00:32:49.322294 | 
2025-11-20 00:32:49.322449 | PLAY [all:!appliance*]
2025-11-20 00:32:49.347800 | 
2025-11-20 00:32:49.347937 | TASK [unregister the node]
2025-11-20 00:32:49.882308 | controller | skipping: Conditional result was False
2025-11-20 00:32:49.895482 | 
2025-11-20 00:32:49.895662 | TASK [include_role : fetch-output]
2025-11-20 00:32:49.936059 | controller | ok
2025-11-20 00:32:49.971964 | 
2025-11-20 00:32:49.972140 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-20 00:32:50.048872 | controller | skipping: Conditional result was False
2025-11-20 00:32:50.057520 | 
2025-11-20 00:32:50.057659 | TASK [fetch-output : Set log path for single node]
2025-11-20 00:32:50.101468 | controller | ok
2025-11-20 00:32:50.108281 | 
2025-11-20 00:32:50.108371 | LOOP [fetch-output : Ensure local output dirs]
2025-11-20 00:32:50.550163 | controller -> localhost | ok: "/var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/work/logs"
2025-11-20 00:32:50.776742 | controller -> localhost | changed: "/var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/work/artifacts"
2025-11-20 00:32:51.012474 | controller -> localhost | changed: "/var/lib/zuul/builds/6e39ad2965fb4c3b8b6498089679a9b1/work/docs"
2025-11-20 00:32:51.032418 | 
2025-11-20 00:32:51.032579 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-20 00:32:51.646817 | controller | changed:
2025-11-20 00:32:51.647046 | controller | .d..t...... ./
2025-11-20 00:32:51.647080 | controller | cd+++++++++ controller/
2025-11-20 00:32:51.647117 | controller | changed: All items complete
2025-11-20 00:32:51.647139 | 
2025-11-20 00:32:52.086291 | controller | changed: .d..t...... ./
2025-11-20 00:32:52.534503 | controller | changed: .d..t...... ./
2025-11-20 00:32:52.562475 | 
2025-11-20 00:32:52.562624 | TASK [include_role : fetch-output-openshift]
2025-11-20 00:32:52.577755 | controller | skipping: Conditional result was False
2025-11-20 00:32:52.585279 | 
2025-11-20 00:32:52.585477 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-20 00:32:52.612345 | controller | skipping: Conditional result was False
2025-11-20 00:32:52.622266 | controller | skipping: Conditional result was False
2025-11-20 00:32:52.662149 | 
2025-11-20 00:32:52.662260 | PLAY [localhost]
2025-11-20 00:32:52.677297 | 
2025-11-20 00:32:52.677432 | TASK [Run Zuul manifest role]
2025-11-20 00:32:52.698676 | localhost | ok
2025-11-20 00:32:52.714986 | 
2025-11-20 00:32:52.715133 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-20 00:32:53.174563 | localhost | changed
2025-11-20 00:32:53.182047 | 
2025-11-20 00:32:53.182164 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-20 00:32:53.214577 | localhost | ok
2025-11-20 00:32:53.223820 | 
2025-11-20 00:32:53.223904 | TASK [Set zuul-log-path fact]
2025-11-20 00:32:53.242687 | localhost | ok
2025-11-20 00:32:53.258755 | 
2025-11-20 00:32:53.258873 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-20 00:32:53.287978 | localhost | ok
2025-11-20 00:32:53.297126 | 
2025-11-20 00:32:53.297216 | LOOP [Run upload-logs-swift role]
2025-11-20 00:32:53.321313 | localhost | Output suppressed because no_log was given
2025-11-20 00:32:53.347846 | 
2025-11-20 00:32:53.347965 | TASK [Set zuul-log-path fact]
2025-11-20 00:32:53.383246 | localhost | skipping: Conditional result was False
2025-11-20 00:32:53.390252 | 
2025-11-20 00:32:53.390374 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-20 00:32:53.839962 | localhost -> localhost | ok: Runtime: 0:00:00.007055
2025-11-20 00:32:53.877593 | 
2025-11-20 00:32:53.877755 | TASK [upload-logs-swift : Upload logs to swift]