2025-12-06 00:32:14.473141 | Job console starting... 2025-12-06 00:32:14.485101 | Updating repositories 2025-12-06 00:32:14.623262 | Preparing job workspace 2025-12-06 00:32:18.490705 | Running Ansible setup... 2025-12-06 00:32:25.879416 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-06 00:32:26.492213 | 2025-12-06 00:32:26.492379 | PLAY [localhost] 2025-12-06 00:32:26.502384 | 2025-12-06 00:32:26.502494 | TASK [Gathering Facts] 2025-12-06 00:32:27.504696 | localhost | ok 2025-12-06 00:32:27.539948 | 2025-12-06 00:32:27.540169 | TASK [Setup log path fact] 2025-12-06 00:32:27.559705 | localhost | ok 2025-12-06 00:32:27.576934 | 2025-12-06 00:32:27.577086 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-06 00:32:27.614084 | localhost | ok 2025-12-06 00:32:27.628276 | 2025-12-06 00:32:27.628429 | TASK [emit-job-header : Print job information] 2025-12-06 00:32:27.679824 | # Job Information 2025-12-06 00:32:27.680065 | Ansible Version: 2.15.12 2025-12-06 00:32:27.680112 | Job: ansible-test-sanity-docker-milestone 2025-12-06 00:32:27.680141 | Pipeline: periodic 2025-12-06 00:32:27.680167 | Executor: ze03.softwarefactory-project.io 2025-12-06 00:32:27.680193 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-06 00:32:27.680221 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/a6b/ansible/a6b5779e56e24709a0c93515f6e41e00/ 2025-12-06 00:32:27.680247 | Event ID: a444be38dc2a48ab869f0b68785b4d55 2025-12-06 00:32:27.685949 | 2025-12-06 00:32:27.686041 | LOOP [emit-job-header : Print node information] 2025-12-06 00:32:27.806937 | localhost | ok: 2025-12-06 00:32:27.807251 | localhost | # Node Information 2025-12-06 00:32:27.807286 | localhost | Inventory Hostname: controller 2025-12-06 00:32:27.807311 | localhost | Hostname: np0005548519 2025-12-06 00:32:27.807336 | localhost | Username: zuul 2025-12-06 00:32:27.807362 | localhost | Distro: Fedora 37 2025-12-06 00:32:27.807385 | localhost | Provider: ansible-vexxhost-ams1 2025-12-06 00:32:27.807408 | localhost | Region: ams1 2025-12-06 00:32:27.807430 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-06 00:32:27.807451 | localhost | Product Name: OpenStack Nova 2025-12-06 00:32:27.807472 | localhost | Interface IP: 38.129.16.227 2025-12-06 00:32:27.830249 | 2025-12-06 00:32:27.830441 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-06 00:32:28.242288 | localhost -> localhost | changed 2025-12-06 00:32:28.248546 | 2025-12-06 00:32:28.248615 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-06 00:32:29.161365 | localhost -> localhost | changed 2025-12-06 00:32:29.182251 | 2025-12-06 00:32:29.182354 | PLAY [all:!appliance*] 2025-12-06 00:32:29.198610 | 2025-12-06 00:32:29.198706 | TASK [include_role : start-zuul-console] 2025-12-06 00:32:29.219132 | controller | ok 2025-12-06 00:32:29.233058 | 2025-12-06 00:32:29.233129 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-06 00:32:30.270339 | controller | ok 2025-12-06 00:32:30.300228 | 2025-12-06 00:32:30.300399 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-06 00:32:32.323439 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-06 00:32:32.337849 | 2025-12-06 00:32:32.337987 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-06 00:32:32.709439 | controller | skipping: Conditional result was False 2025-12-06 00:32:32.716822 | 2025-12-06 00:32:32.716896 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-06 00:32:32.741947 | controller | skipping: Conditional result was False 2025-12-06 00:32:32.749218 | 2025-12-06 00:32:32.749307 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-06 00:32:32.775799 | controller | skipping: Conditional result was False 2025-12-06 00:32:32.784166 | 2025-12-06 00:32:32.784306 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-06 00:32:32.818801 | controller | skipping: Conditional result was False 2025-12-06 00:32:32.834685 | 2025-12-06 00:32:32.834960 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-06 00:32:32.866064 | controller | skipping: Conditional result was False 2025-12-06 00:32:32.876811 | 2025-12-06 00:32:32.876913 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-06 00:32:32.913520 | controller | skipping: Conditional result was False 2025-12-06 00:32:32.930668 | 2025-12-06 00:32:32.930787 | TASK [Disable Fedora Modular] 2025-12-06 00:32:34.046037 | controller | changed 2025-12-06 00:32:34.060837 | 2025-12-06 00:32:34.060988 | TASK [Enable EPEL] 2025-12-06 00:32:34.089978 | controller | skipping: Conditional result was False 2025-12-06 00:32:34.105077 | 2025-12-06 00:32:34.105274 | TASK [Register the RHEL node] 2025-12-06 00:32:34.528662 | 2025-12-06 00:32:34.528896 | TASK [Show the subscription-manager status] 2025-12-06 00:32:34.902706 | controller | skipping: Conditional result was False 2025-12-06 00:32:34.910535 | 2025-12-06 00:32:34.910623 | TASK [Enable EPEL on RHEL] 2025-12-06 00:32:35.281043 | controller | skipping: Conditional result was False 2025-12-06 00:32:35.296990 | 2025-12-06 00:32:35.297190 | TASK [Install git and tox] 2025-12-06 00:34:39.106312 | controller | changed 2025-12-06 00:34:39.115043 | 2025-12-06 00:34:39.115127 | TASK [include_role : prepare-workspace] 2025-12-06 00:34:39.151998 | controller | ok 2025-12-06 00:34:39.175798 | 2025-12-06 00:34:39.175941 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-06 00:34:40.017573 | controller | ok 2025-12-06 00:34:40.025142 | 2025-12-06 00:34:40.025236 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-06 00:34:55.345960 | controller | Output suppressed because no_log was given 2025-12-06 00:34:55.356877 | 2025-12-06 00:34:55.356986 | TASK [include_role : prepare-workspace-openshift] 2025-12-06 00:34:55.382828 | controller | skipping: Conditional result was False 2025-12-06 00:34:55.410076 | 2025-12-06 00:34:55.410180 | PLAY [all:!appliance] 2025-12-06 00:34:55.428670 | 2025-12-06 00:34:55.428851 | TASK [Run add-build-sshkey role (RSA)] 2025-12-06 00:34:55.460202 | controller | ok 2025-12-06 00:34:55.476184 | 2025-12-06 00:34:55.476333 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-06 00:34:55.738922 | controller -> localhost | ok 2025-12-06 00:34:55.754680 | 2025-12-06 00:34:55.754925 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-06 00:34:55.795226 | controller | ok 2025-12-06 00:34:55.821761 | controller | included: /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-06 00:34:55.831048 | 2025-12-06 00:34:55.831197 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-06 00:34:56.348906 | controller -> localhost | Generating public/private rsa key pair. 2025-12-06 00:34:56.349192 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/work/a6b5779e56e24709a0c93515f6e41e00_id_rsa. 2025-12-06 00:34:56.349221 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/work/a6b5779e56e24709a0c93515f6e41e00_id_rsa.pub. 2025-12-06 00:34:56.349241 | controller -> localhost | The key fingerprint is: 2025-12-06 00:34:56.349261 | controller -> localhost | SHA256:UOKpfoDTVhlCWVVYXdBrJb0dWgYiHEhWKxKGrRkWVtw zuul-build-sshkey 2025-12-06 00:34:56.349280 | controller -> localhost | The key's randomart image is: 2025-12-06 00:34:56.349298 | controller -> localhost | +---[RSA 2048]----+ 2025-12-06 00:34:56.349316 | controller -> localhost | | +O**+*B+o.=o. | 2025-12-06 00:34:56.349334 | controller -> localhost | | .+o=oE..o o o+o| 2025-12-06 00:34:56.349352 | controller -> localhost | | . +.*. . +++| 2025-12-06 00:34:56.349369 | controller -> localhost | | = o... .o..| 2025-12-06 00:34:56.349386 | controller -> localhost | | o = S . | 2025-12-06 00:34:56.349415 | controller -> localhost | | + . | 2025-12-06 00:34:56.349442 | controller -> localhost | | . . | 2025-12-06 00:34:56.349462 | controller -> localhost | | . | 2025-12-06 00:34:56.349481 | controller -> localhost | | | 2025-12-06 00:34:56.349501 | controller -> localhost | +----[SHA256]-----+ 2025-12-06 00:34:56.349578 | controller -> localhost | ok: Runtime: 0:00:00.058889 2025-12-06 00:34:56.357721 | 2025-12-06 00:34:56.357800 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-06 00:34:56.389378 | controller | ok 2025-12-06 00:34:56.400074 | controller | included: /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-06 00:34:56.410684 | 2025-12-06 00:34:56.410827 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-06 00:34:56.438628 | controller | skipping: Conditional result was False 2025-12-06 00:34:56.447224 | 2025-12-06 00:34:56.447306 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-06 00:34:57.538616 | controller | changed 2025-12-06 00:34:57.552211 | 2025-12-06 00:34:57.552355 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-06 00:34:58.230410 | controller | ok 2025-12-06 00:34:58.243487 | 2025-12-06 00:34:58.243623 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-06 00:35:01.234139 | controller | changed 2025-12-06 00:35:01.241936 | 2025-12-06 00:35:01.242083 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-06 00:35:04.262247 | controller | changed 2025-12-06 00:35:04.272704 | 2025-12-06 00:35:04.272826 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-06 00:35:04.312982 | controller | skipping: Conditional result was False 2025-12-06 00:35:04.324502 | 2025-12-06 00:35:04.324628 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-06 00:35:04.834350 | controller -> localhost | changed 2025-12-06 00:35:04.862293 | 2025-12-06 00:35:04.862450 | TASK [add-build-sshkey : Add back temp key] 2025-12-06 00:35:05.156008 | controller -> localhost | Identity added: /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/work/a6b5779e56e24709a0c93515f6e41e00_id_rsa (zuul-build-sshkey) 2025-12-06 00:35:05.156423 | controller -> localhost | ok: Runtime: 0:00:00.010604 2025-12-06 00:35:05.171190 | 2025-12-06 00:35:05.171323 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-06 00:35:06.123083 | controller | ok 2025-12-06 00:35:06.136278 | 2025-12-06 00:35:06.136439 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-06 00:35:06.164839 | controller | skipping: Conditional result was False 2025-12-06 00:35:06.191850 | 2025-12-06 00:35:06.192086 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-06 00:35:06.235476 | controller | ok 2025-12-06 00:35:06.274820 | 2025-12-06 00:35:06.274996 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-06 00:35:06.590973 | controller -> localhost | ok 2025-12-06 00:35:06.598346 | 2025-12-06 00:35:06.598414 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-06 00:35:06.630202 | controller | ok 2025-12-06 00:35:06.645635 | controller | included: /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-06 00:35:06.654161 | 2025-12-06 00:35:06.654244 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-06 00:35:07.008828 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-06 00:35:07.009285 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/work/a6b5779e56e24709a0c93515f6e41e00_id_ecdsa. 2025-12-06 00:35:07.009331 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/work/a6b5779e56e24709a0c93515f6e41e00_id_ecdsa.pub. 2025-12-06 00:35:07.009375 | controller -> localhost | The key fingerprint is: 2025-12-06 00:35:07.009405 | controller -> localhost | SHA256:CVyPpc26mF2H52ROo8PeaZ7nW61NN2NklKL/01+yaA8 zuul-build-sshkey 2025-12-06 00:35:07.009433 | controller -> localhost | The key's randomart image is: 2025-12-06 00:35:07.009460 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-06 00:35:07.009486 | controller -> localhost | | . . | 2025-12-06 00:35:07.009512 | controller -> localhost | | . . B .| 2025-12-06 00:35:07.009537 | controller -> localhost | | o o + . o | 2025-12-06 00:35:07.009578 | controller -> localhost | | . o .. o | 2025-12-06 00:35:07.009605 | controller -> localhost | | S o.B o | 2025-12-06 00:35:07.009631 | controller -> localhost | | + + X..o .| 2025-12-06 00:35:07.009656 | controller -> localhost | | o o + E..+B| 2025-12-06 00:35:07.009680 | controller -> localhost | | . oo=+O*| 2025-12-06 00:35:07.009705 | controller -> localhost | | .+*+*o=| 2025-12-06 00:35:07.009750 | controller -> localhost | +----[SHA256]-----+ 2025-12-06 00:35:07.009834 | controller -> localhost | ok: Runtime: 0:00:00.015976 2025-12-06 00:35:07.026524 | 2025-12-06 00:35:07.026798 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-06 00:35:07.072909 | controller | ok 2025-12-06 00:35:07.094098 | controller | included: /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-06 00:35:07.109772 | 2025-12-06 00:35:07.109891 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-06 00:35:07.146050 | controller | skipping: Conditional result was False 2025-12-06 00:35:07.156762 | 2025-12-06 00:35:07.156878 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-06 00:35:08.106997 | controller | changed 2025-12-06 00:35:08.122838 | 2025-12-06 00:35:08.123046 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-06 00:35:08.779047 | controller | ok 2025-12-06 00:35:08.795140 | 2025-12-06 00:35:08.795296 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-06 00:35:11.836157 | controller | changed 2025-12-06 00:35:11.847104 | 2025-12-06 00:35:11.847276 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-06 00:35:14.799042 | controller | changed 2025-12-06 00:35:14.826923 | 2025-12-06 00:35:14.827190 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-06 00:35:14.857204 | controller | skipping: Conditional result was False 2025-12-06 00:35:14.881504 | 2025-12-06 00:35:14.881660 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-06 00:35:15.150361 | controller -> localhost | changed 2025-12-06 00:35:15.162972 | 2025-12-06 00:35:15.163052 | TASK [add-build-sshkey : Add back temp key] 2025-12-06 00:35:15.493469 | controller -> localhost | Identity added: /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/work/a6b5779e56e24709a0c93515f6e41e00_id_ecdsa (zuul-build-sshkey) 2025-12-06 00:35:15.493930 | controller -> localhost | ok: Runtime: 0:00:00.014906 2025-12-06 00:35:15.509112 | 2025-12-06 00:35:15.509340 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-06 00:35:16.218657 | controller | ok 2025-12-06 00:35:16.232394 | 2025-12-06 00:35:16.232614 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-06 00:35:16.273679 | controller | skipping: Conditional result was False 2025-12-06 00:35:16.300522 | 2025-12-06 00:35:16.300661 | TASK [include_role : remove-zuul-sshkey] 2025-12-06 00:35:16.328306 | controller | skipping: Conditional result was False 2025-12-06 00:35:16.342513 | 2025-12-06 00:35:16.342656 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-06 00:35:16.995048 | controller | ok: "logs" 2025-12-06 00:35:16.995409 | controller | ok: All items complete 2025-12-06 00:35:16.995449 | 2025-12-06 00:35:17.593168 | controller | ok: "artifacts" 2025-12-06 00:35:18.267548 | controller | ok: "docs" 2025-12-06 00:35:18.293943 | 2025-12-06 00:35:18.294163 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-06 00:35:18.972417 | controller | changed: "logs" 2025-12-06 00:35:19.592778 | controller | changed: "artifacts" 2025-12-06 00:35:20.187219 | controller | changed: "docs" 2025-12-06 00:35:20.223874 | 2025-12-06 00:35:20.224029 | PLAY RECAP 2025-12-06 00:35:20.224095 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-06 00:35:20.224125 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-06 00:35:20.224143 | 2025-12-06 00:35:20.371317 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-06 00:35:20.372301 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-06 00:35:21.078894 | 2025-12-06 00:35:21.079094 | PLAY [all] 2025-12-06 00:35:21.105948 | 2025-12-06 00:35:21.106126 | TASK [Install binary dependencies] 2025-12-06 00:35:21.181321 | controller | ok 2025-12-06 00:35:21.212414 | 2025-12-06 00:35:21.212658 | TASK [bindep : Include find tasks] 2025-12-06 00:35:21.249943 | controller | ok 2025-12-06 00:35:21.262603 | controller | included: /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-06 00:35:21.272864 | 2025-12-06 00:35:21.273065 | TASK [bindep : Look for bindep.txt] 2025-12-06 00:35:22.246480 | controller | ok 2025-12-06 00:35:22.261661 | 2025-12-06 00:35:22.261840 | TASK [bindep : Define bindep_file fact] 2025-12-06 00:35:22.288927 | controller | skipping: Conditional result was False 2025-12-06 00:35:22.298363 | 2025-12-06 00:35:22.298457 | TASK [bindep : Look for other-requirements.txt] 2025-12-06 00:35:22.924036 | controller | ok 2025-12-06 00:35:22.932576 | 2025-12-06 00:35:22.932688 | TASK [bindep : Define bindep_file fact] 2025-12-06 00:35:22.970010 | controller | skipping: Conditional result was False 2025-12-06 00:35:22.985146 | 2025-12-06 00:35:22.985318 | TASK [bindep : Look for bindep fallback file] 2025-12-06 00:35:23.034651 | controller | skipping: Conditional result was False 2025-12-06 00:35:23.049111 | 2025-12-06 00:35:23.049316 | TASK [bindep : Define bindep_file fact] 2025-12-06 00:35:23.078091 | controller | skipping: Conditional result was False 2025-12-06 00:35:23.092572 | 2025-12-06 00:35:23.092786 | TASK [bindep : Include bindep tasks] 2025-12-06 00:35:23.131272 | controller | skipping: Conditional result was False 2025-12-06 00:35:23.146689 | 2025-12-06 00:35:23.147033 | TASK [bindep : Include install tasks] 2025-12-06 00:35:23.176658 | controller | skipping: Conditional result was False 2025-12-06 00:35:23.191796 | 2025-12-06 00:35:23.191944 | LOOP [bindep : Include package tasks] 2025-12-06 00:35:23.282894 | 2025-12-06 00:35:23.283480 | TASK [Run test-setup role] 2025-12-06 00:35:23.308149 | controller | ok 2025-12-06 00:35:23.326893 | 2025-12-06 00:35:23.327047 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-06 00:35:24.022989 | controller | ok 2025-12-06 00:35:24.036872 | 2025-12-06 00:35:24.037065 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-06 00:35:24.414864 | controller | skipping: Conditional result was False 2025-12-06 00:35:24.471645 | 2025-12-06 00:35:24.471814 | PLAY RECAP 2025-12-06 00:35:24.471878 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-06 00:35:24.471908 | 2025-12-06 00:35:24.614951 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-06 00:35:24.615930 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-06 00:35:25.266705 | 2025-12-06 00:35:25.266892 | PLAY [controller] 2025-12-06 00:35:25.288278 | 2025-12-06 00:35:25.288445 | TASK [Create the /root directory] 2025-12-06 00:35:26.349142 | controller | ok 2025-12-06 00:35:26.362105 | 2025-12-06 00:35:26.362257 | TASK [Install glibc-langpack-en] 2025-12-06 00:35:34.652182 | controller | ok: Nothing to do 2025-12-06 00:35:34.663422 | 2025-12-06 00:35:34.663534 | TASK [Ensure controller directory exists] 2025-12-06 00:35:35.488105 | controller | changed 2025-12-06 00:35:35.501857 | 2025-12-06 00:35:35.502091 | TASK [Install container runtime] 2025-12-06 00:35:35.579762 | controller | ok 2025-12-06 00:35:35.619473 | 2025-12-06 00:35:35.619616 | LOOP [ensure-podman : Find distribution installation] 2025-12-06 00:35:35.650496 | controller | ok: "/var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-06 00:35:35.662280 | controller | included: /var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-06 00:35:35.668621 | 2025-12-06 00:35:35.668688 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-06 00:37:35.796080 | controller | changed 2025-12-06 00:37:35.804180 | 2025-12-06 00:37:35.804255 | TASK [ensure-podman : Fetch podman version] 2025-12-06 00:37:36.970736 | controller | Client: Podman Engine 2025-12-06 00:37:37.013601 | controller | Version: 4.6.2 2025-12-06 00:37:37.013653 | controller | API Version: 4.6.2 2025-12-06 00:37:37.013661 | controller | Go Version: go1.19.12 2025-12-06 00:37:37.013681 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-06 00:37:37.013689 | controller | OS/Arch: linux/amd64 2025-12-06 00:37:37.167225 | controller | ok: Runtime: 0:00:00.295076 2025-12-06 00:37:37.177781 | 2025-12-06 00:37:37.177950 | TASK [ensure-podman : Print podman version installed] 2025-12-06 00:37:37.213408 | Podman version: Client: Podman Engine 2025-12-06 00:37:37.213644 | Version: 4.6.2 2025-12-06 00:37:37.213672 | API Version: 4.6.2 2025-12-06 00:37:37.213692 | Go Version: go1.19.12 2025-12-06 00:37:37.213709 | Built: Mon Aug 28 19:38:31 2023 2025-12-06 00:37:37.213747 | OS/Arch: linux/amd64 2025-12-06 00:37:37.220786 | 2025-12-06 00:37:37.220875 | TASK [ensure-podman : Validate podman engine] 2025-12-06 00:37:37.575685 | controller | skipping: Conditional result was False 2025-12-06 00:37:37.591464 | 2025-12-06 00:37:37.591679 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-06 00:37:37.619938 | controller | skipping: Conditional result was False 2025-12-06 00:37:37.646038 | 2025-12-06 00:37:37.646205 | TASK [Ensure python3.8 is present] 2025-12-06 00:37:37.661273 | controller | skipping: Conditional result was False 2025-12-06 00:37:37.672552 | 2025-12-06 00:37:37.672716 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-06 00:37:37.697515 | controller | ok 2025-12-06 00:37:37.727614 | 2025-12-06 00:37:37.727796 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-06 00:37:41.219595 | controller | ok: Nothing to do 2025-12-06 00:37:41.232124 | 2025-12-06 00:37:41.232254 | TASK [our-ensure-python : Also install python3-devel] 2025-12-06 00:37:55.472087 | controller | changed 2025-12-06 00:37:55.497846 | 2025-12-06 00:37:55.497999 | TASK [Run ensure-virtualenv role] 2025-12-06 00:37:55.524861 | controller | ok 2025-12-06 00:37:55.556534 | 2025-12-06 00:37:55.556753 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-06 00:37:56.396029 | controller | /usr/bin/virtualenv 2025-12-06 00:37:56.936136 | controller | ok: Runtime: 0:00:00.005026 2025-12-06 00:37:56.944650 | 2025-12-06 00:37:56.944763 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-06 00:37:56.983036 | controller | skipping: Conditional result was False 2025-12-06 00:37:56.983490 | controller | ok: All items complete 2025-12-06 00:37:56.983530 | 2025-12-06 00:37:57.017990 | 2025-12-06 00:37:57.018264 | TASK [Find the full path of the Python interpreter] 2025-12-06 00:37:57.796737 | controller | /usr/bin/python3 2025-12-06 00:37:58.400505 | controller | ok 2025-12-06 00:37:58.409421 | 2025-12-06 00:37:58.409643 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-06 00:38:00.331447 | controller | created virtual environment CPython3.11.0.final.0-64 in 889ms 2025-12-06 00:38:00.380095 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-06 00:38:00.380151 | 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-06 00:38:00.380166 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-06 00:38:00.380188 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-06 00:38:00.787211 | controller | changed 2025-12-06 00:38:00.804848 | 2025-12-06 00:38:00.805071 | TASK [Set selinux package] 2025-12-06 00:38:00.848951 | controller | ok 2025-12-06 00:38:00.863693 | 2025-12-06 00:38:00.864122 | TASK [Set selinux package (Fedora)] 2025-12-06 00:38:00.913246 | controller | ok 2025-12-06 00:38:00.921406 | 2025-12-06 00:38:00.921507 | TASK [Install selinux into virtualenv] 2025-12-06 00:38:03.844661 | controller | Collecting selinux-please-lie-to-me 2025-12-06 00:38:03.902904 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-06 00:38:04.436487 | controller | Collecting setuptools<50.0.0 2025-12-06 00:38:04.441946 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-06 00:38:04.491141 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 19.4 MB/s eta 0:00:00 2025-12-06 00:38:04.686254 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-06 00:38:04.686572 | controller | Attempting uninstall: setuptools 2025-12-06 00:38:04.692422 | controller | Found existing installation: setuptools 62.6.0 2025-12-06 00:38:04.787132 | controller | Uninstalling setuptools-62.6.0: 2025-12-06 00:38:04.803797 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-06 00:38:05.554729 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-06 00:38:05.762454 | controller | 2025-12-06 00:38:06.038476 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-06 00:38:06.038523 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-06 00:38:06.325688 | controller | ok: Runtime: 0:00:04.304979 2025-12-06 00:38:06.335172 | 2025-12-06 00:38:06.335295 | TASK [Install pytest-forked into virtualenv] 2025-12-06 00:38:07.876645 | controller | Collecting pytest-forked 2025-12-06 00:38:07.943250 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-06 00:38:08.011724 | controller | Collecting py 2025-12-06 00:38:08.020770 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-06 00:38:08.057033 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.0 MB/s eta 0:00:00 2025-12-06 00:38:08.245033 | controller | Collecting pytest>=3.10 2025-12-06 00:38:08.250100 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-12-06 00:38:08.273903 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 26.9 MB/s eta 0:00:00 2025-12-06 00:38:08.323720 | controller | Collecting iniconfig>=1.0.1 2025-12-06 00:38:08.328523 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-06 00:38:08.396621 | controller | Collecting packaging>=22 2025-12-06 00:38:08.401093 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-06 00:38:08.412327 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.8 MB/s eta 0:00:00 2025-12-06 00:38:08.453462 | controller | Collecting pluggy<2,>=1.5 2025-12-06 00:38:08.457947 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-06 00:38:08.518700 | controller | Collecting pygments>=2.7.2 2025-12-06 00:38:08.523118 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-06 00:38:08.544946 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 65.2 MB/s eta 0:00:00 2025-12-06 00:38:08.645493 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-06 00:38:10.832686 | 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-12-06 00:38:10.850004 | controller | 2025-12-06 00:38:11.051209 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-06 00:38:11.051264 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-06 00:38:11.210148 | controller | ok: Runtime: 0:00:03.918258 2025-12-06 00:38:11.224595 | 2025-12-06 00:38:11.224869 | TASK [Update pip] 2025-12-06 00:38:12.588534 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-06 00:38:12.902758 | controller | Collecting pip 2025-12-06 00:38:12.990472 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-06 00:38:13.081699 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 21.6 MB/s eta 0:00:00 2025-12-06 00:38:13.215903 | controller | Installing collected packages: pip 2025-12-06 00:38:13.216290 | controller | Attempting uninstall: pip 2025-12-06 00:38:13.223770 | controller | Found existing installation: pip 22.2.2 2025-12-06 00:38:13.466548 | controller | Uninstalling pip-22.2.2: 2025-12-06 00:38:13.495192 | controller | Successfully uninstalled pip-22.2.2 2025-12-06 00:38:15.326871 | controller | Successfully installed pip-25.3 2025-12-06 00:38:16.139112 | controller | ok: Runtime: 0:00:03.589067 2025-12-06 00:38:16.148878 | 2025-12-06 00:38:16.149166 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-06 00:38:17.025588 | controller | changed 2025-12-06 00:38:17.039197 | 2025-12-06 00:38:17.039386 | TASK [Install ansible into virtualenv] 2025-12-06 00:38:18.286524 | controller | Processing ./src/github.com/ansible/ansible 2025-12-06 00:38:18.291798 | controller | Installing build dependencies: started 2025-12-06 00:38:20.143206 | controller | Installing build dependencies: finished with status 'done' 2025-12-06 00:38:21.651960 | controller | Getting requirements to build wheel: started 2025-12-06 00:38:21.652048 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-06 00:38:21.655049 | controller | Preparing metadata (pyproject.toml): started 2025-12-06 00:38:22.485681 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-06 00:38:22.489665 | 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-06 00:38:22.495214 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-06 00:38:22.976795 | controller | ERROR 2025-12-06 00:38:22.977076 | controller | { 2025-12-06 00:38:22.977108 | controller | "delta": "0:00:04.926295", 2025-12-06 00:38:22.977128 | controller | "end": "2025-12-06 00:38:22.655845", 2025-12-06 00:38:22.977146 | controller | "msg": "non-zero return code", 2025-12-06 00:38:22.977182 | controller | "rc": 1, 2025-12-06 00:38:22.977200 | controller | "start": "2025-12-06 00:38:17.729550" 2025-12-06 00:38:22.977216 | controller | } failure 2025-12-06 00:38:22.979334 | 2025-12-06 00:38:22.979385 | PLAY RECAP 2025-12-06 00:38:22.979432 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-06 00:38:22.979453 | 2025-12-06 00:38:23.124984 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-06 00:38:23.127628 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-06 00:38:23.731233 | 2025-12-06 00:38:23.731403 | PLAY [all] 2025-12-06 00:38:23.754022 | 2025-12-06 00:38:23.754158 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-06 00:38:25.604983 | controller | changed: non-zero return code 2025-12-06 00:38:25.623841 | 2025-12-06 00:38:25.624170 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-06 00:38:25.653767 | controller | skipping: Conditional result was False 2025-12-06 00:38:25.668608 | 2025-12-06 00:38:25.668826 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-06 00:38:25.714239 | 2025-12-06 00:38:25.714567 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-06 00:38:25.757672 | 2025-12-06 00:38:25.758097 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-06 00:38:25.786410 | controller | skipping: Conditional result was False 2025-12-06 00:38:25.801121 | 2025-12-06 00:38:25.801314 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-06 00:38:25.843641 | 2025-12-06 00:38:25.844000 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-06 00:38:25.872373 | controller | skipping: Conditional result was False 2025-12-06 00:38:25.886544 | 2025-12-06 00:38:25.886713 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-06 00:38:25.915686 | controller | skipping: Conditional result was False 2025-12-06 00:38:25.929681 | 2025-12-06 00:38:25.929872 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-06 00:38:25.959288 | controller | skipping: Conditional result was False 2025-12-06 00:38:26.007483 | 2025-12-06 00:38:26.007574 | PLAY RECAP 2025-12-06 00:38:26.007634 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-06 00:38:26.007662 | 2025-12-06 00:38:26.139025 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-06 00:38:26.140773 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-06 00:38:26.733829 | 2025-12-06 00:38:26.733980 | PLAY [all:!appliance*] 2025-12-06 00:38:26.755718 | 2025-12-06 00:38:26.755846 | TASK [unregister the node] 2025-12-06 00:38:27.113574 | controller | skipping: Conditional result was False 2025-12-06 00:38:27.126485 | 2025-12-06 00:38:27.126656 | TASK [include_role : fetch-output] 2025-12-06 00:38:27.185512 | controller | ok 2025-12-06 00:38:27.225159 | 2025-12-06 00:38:27.225285 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-06 00:38:27.303713 | controller | skipping: Conditional result was False 2025-12-06 00:38:27.317913 | 2025-12-06 00:38:27.318061 | TASK [fetch-output : Set log path for single node] 2025-12-06 00:38:27.370696 | controller | ok 2025-12-06 00:38:27.383338 | 2025-12-06 00:38:27.383439 | LOOP [fetch-output : Ensure local output dirs] 2025-12-06 00:38:27.874378 | controller -> localhost | ok: "/var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/work/logs" 2025-12-06 00:38:28.112912 | controller -> localhost | changed: "/var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/work/artifacts" 2025-12-06 00:38:28.378157 | controller -> localhost | changed: "/var/lib/zuul/builds/a6b5779e56e24709a0c93515f6e41e00/work/docs" 2025-12-06 00:38:28.404302 | 2025-12-06 00:38:28.404608 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-06 00:38:30.769354 | controller | changed: 2025-12-06 00:38:30.769795 | controller | .d..t...... ./ 2025-12-06 00:38:30.769865 | controller | cd+++++++++ controller/ 2025-12-06 00:38:30.769941 | controller | changed: All items complete 2025-12-06 00:38:30.769986 | 2025-12-06 00:38:32.877806 | controller | changed: .d..t...... ./ 2025-12-06 00:38:34.996530 | controller | changed: .d..t...... ./ 2025-12-06 00:38:35.026075 | 2025-12-06 00:38:35.026302 | TASK [include_role : fetch-output-openshift] 2025-12-06 00:38:35.053476 | controller | skipping: Conditional result was False 2025-12-06 00:38:35.070002 | 2025-12-06 00:38:35.070176 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-06 00:38:35.122482 | controller | skipping: Conditional result was False 2025-12-06 00:38:35.140687 | controller | skipping: Conditional result was False 2025-12-06 00:38:35.202985 | 2025-12-06 00:38:35.203139 | PLAY [localhost] 2025-12-06 00:38:35.221220 | 2025-12-06 00:38:35.221346 | TASK [Run Zuul manifest role] 2025-12-06 00:38:35.252624 | localhost | ok 2025-12-06 00:38:35.271471 | 2025-12-06 00:38:35.271582 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-06 00:38:35.685529 | localhost | changed 2025-12-06 00:38:35.695335 | 2025-12-06 00:38:35.695468 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-06 00:38:35.743201 | localhost | ok 2025-12-06 00:38:35.763536 | 2025-12-06 00:38:35.763669 | TASK [Set zuul-log-path fact] 2025-12-06 00:38:35.822358 | localhost | ok 2025-12-06 00:38:35.837852 | 2025-12-06 00:38:35.837939 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-06 00:38:35.878644 | localhost | ok 2025-12-06 00:38:35.890254 | 2025-12-06 00:38:35.890372 | LOOP [Run upload-logs-swift role] 2025-12-06 00:38:35.935850 | localhost | Output suppressed because no_log was given 2025-12-06 00:38:35.981653 | 2025-12-06 00:38:35.981834 | TASK [Set zuul-log-path fact] 2025-12-06 00:38:36.018043 | localhost | skipping: Conditional result was False 2025-12-06 00:38:36.031166 | 2025-12-06 00:38:36.031353 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-06 00:38:36.489508 | localhost -> localhost | ok: Runtime: 0:00:00.008869 2025-12-06 00:38:36.495490 | 2025-12-06 00:38:36.495561 | TASK [upload-logs-swift : Upload logs to swift]