2025-12-25 00:21:29.857786 | Job console starting... 2025-12-25 00:21:29.866369 | Updating repositories 2025-12-25 00:21:30.011556 | Preparing job workspace 2025-12-25 00:21:34.144772 | Running Ansible setup... 2025-12-25 00:21:38.886833 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-25 00:21:39.530540 | 2025-12-25 00:21:39.530756 | PLAY [localhost] 2025-12-25 00:21:39.541006 | 2025-12-25 00:21:39.541143 | TASK [Gathering Facts] 2025-12-25 00:21:40.629885 | localhost | ok 2025-12-25 00:21:40.644263 | 2025-12-25 00:21:40.644471 | TASK [Setup log path fact] 2025-12-25 00:21:40.675945 | localhost | ok 2025-12-25 00:21:40.689451 | 2025-12-25 00:21:40.689566 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-25 00:21:40.730839 | localhost | ok 2025-12-25 00:21:40.753103 | 2025-12-25 00:21:40.753438 | TASK [emit-job-header : Print job information] 2025-12-25 00:21:40.786924 | # Job Information 2025-12-25 00:21:40.787141 | Ansible Version: 2.15.12 2025-12-25 00:21:40.787184 | Job: ansible-test-sanity-docker-milestone 2025-12-25 00:21:40.787213 | Pipeline: periodic 2025-12-25 00:21:40.787238 | Executor: ze04.softwarefactory-project.io 2025-12-25 00:21:40.787263 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-25 00:21:40.787296 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/029/ansible/029dd6ceca1f45e48070167ca25d2919/ 2025-12-25 00:21:40.787323 | Event ID: 9bcd164eed0a4284892079c0f800abca 2025-12-25 00:21:40.792766 | 2025-12-25 00:21:40.792862 | LOOP [emit-job-header : Print node information] 2025-12-25 00:21:40.894918 | localhost | ok: 2025-12-25 00:21:40.895211 | localhost | # Node Information 2025-12-25 00:21:40.895253 | localhost | Inventory Hostname: controller 2025-12-25 00:21:40.895287 | localhost | Hostname: np0005570316 2025-12-25 00:21:40.895319 | localhost | Username: zuul 2025-12-25 00:21:40.895356 | localhost | Distro: Fedora 37 2025-12-25 00:21:40.895387 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-25 00:21:40.895416 | localhost | Region: ca-ymq-1 2025-12-25 00:21:40.895446 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-25 00:21:40.895477 | localhost | Product Name: OpenStack Nova 2025-12-25 00:21:40.895509 | localhost | Interface IP: 162.253.55.195 2025-12-25 00:21:40.920153 | 2025-12-25 00:21:40.920375 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-25 00:21:41.389111 | localhost -> localhost | changed 2025-12-25 00:21:41.394818 | 2025-12-25 00:21:41.394893 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-25 00:21:42.401575 | localhost -> localhost | changed 2025-12-25 00:21:42.430029 | 2025-12-25 00:21:42.430142 | PLAY [all:!appliance*] 2025-12-25 00:21:42.447272 | 2025-12-25 00:21:42.447365 | TASK [include_role : start-zuul-console] 2025-12-25 00:21:42.468595 | controller | ok 2025-12-25 00:21:42.482078 | 2025-12-25 00:21:42.482189 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-25 00:21:42.862546 | controller | ok 2025-12-25 00:21:42.884944 | 2025-12-25 00:21:42.885058 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-25 00:22:05.223990 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-25 00:22:05.239756 | 2025-12-25 00:22:05.239942 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-25 00:22:05.793641 | controller | skipping: Conditional result was False 2025-12-25 00:22:05.808084 | 2025-12-25 00:22:05.808250 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-25 00:22:05.835489 | controller | skipping: Conditional result was False 2025-12-25 00:22:05.850607 | 2025-12-25 00:22:05.850893 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-25 00:22:05.869264 | controller | skipping: Conditional result was False 2025-12-25 00:22:05.883946 | 2025-12-25 00:22:05.884145 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-25 00:22:05.921605 | controller | skipping: Conditional result was False 2025-12-25 00:22:05.936208 | 2025-12-25 00:22:05.936420 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-25 00:22:05.963295 | controller | skipping: Conditional result was False 2025-12-25 00:22:05.976872 | 2025-12-25 00:22:05.977064 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-25 00:22:06.003953 | controller | skipping: Conditional result was False 2025-12-25 00:22:06.029856 | 2025-12-25 00:22:06.030064 | TASK [Disable Fedora Modular] 2025-12-25 00:22:06.414186 | controller | changed 2025-12-25 00:22:06.421937 | 2025-12-25 00:22:06.422031 | TASK [Enable EPEL] 2025-12-25 00:22:06.447515 | controller | skipping: Conditional result was False 2025-12-25 00:22:06.463578 | 2025-12-25 00:22:06.463863 | TASK [Register the RHEL node] 2025-12-25 00:22:07.028066 | 2025-12-25 00:22:07.028292 | TASK [Show the subscription-manager status] 2025-12-25 00:22:07.569540 | controller | skipping: Conditional result was False 2025-12-25 00:22:07.580387 | 2025-12-25 00:22:07.580524 | TASK [Enable EPEL on RHEL] 2025-12-25 00:22:07.647588 | controller | skipping: Conditional result was False 2025-12-25 00:22:07.658045 | 2025-12-25 00:22:07.658240 | TASK [Install git and tox] 2025-12-25 00:23:07.352885 | controller | changed 2025-12-25 00:23:07.366463 | 2025-12-25 00:23:07.366597 | TASK [include_role : prepare-workspace] 2025-12-25 00:23:07.402319 | controller | ok 2025-12-25 00:23:07.445374 | 2025-12-25 00:23:07.445566 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-25 00:23:07.696336 | controller | ok 2025-12-25 00:23:07.707638 | 2025-12-25 00:23:07.707798 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-25 00:23:20.098198 | controller | Output suppressed because no_log was given 2025-12-25 00:23:20.114999 | 2025-12-25 00:23:20.115108 | TASK [include_role : prepare-workspace-openshift] 2025-12-25 00:23:20.142087 | controller | skipping: Conditional result was False 2025-12-25 00:23:20.179400 | 2025-12-25 00:23:20.179538 | PLAY [all:!appliance] 2025-12-25 00:23:20.206148 | 2025-12-25 00:23:20.206333 | TASK [Run add-build-sshkey role (RSA)] 2025-12-25 00:23:20.239828 | controller | ok 2025-12-25 00:23:20.255855 | 2025-12-25 00:23:20.255991 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-25 00:23:20.518293 | controller -> localhost | ok 2025-12-25 00:23:20.525112 | 2025-12-25 00:23:20.525191 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-25 00:23:20.556394 | controller | ok 2025-12-25 00:23:20.570961 | controller | included: /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-25 00:23:20.576942 | 2025-12-25 00:23:20.577005 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-25 00:23:21.415641 | controller -> localhost | Generating public/private rsa key pair. 2025-12-25 00:23:21.416053 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/work/029dd6ceca1f45e48070167ca25d2919_id_rsa. 2025-12-25 00:23:21.416118 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/work/029dd6ceca1f45e48070167ca25d2919_id_rsa.pub. 2025-12-25 00:23:21.416165 | controller -> localhost | The key fingerprint is: 2025-12-25 00:23:21.416208 | controller -> localhost | SHA256:IqoPFfNykb1A+6MOEk/chTkBsfcT7rAlQ+SRL23p25Q zuul-build-sshkey 2025-12-25 00:23:21.416250 | controller -> localhost | The key's randomart image is: 2025-12-25 00:23:21.416291 | controller -> localhost | +---[RSA 2048]----+ 2025-12-25 00:23:21.416332 | controller -> localhost | | oo=. | 2025-12-25 00:23:21.416374 | controller -> localhost | | =.O | 2025-12-25 00:23:21.416414 | controller -> localhost | | + %o+. | 2025-12-25 00:23:21.416454 | controller -> localhost | | . B.O=o | 2025-12-25 00:23:21.416492 | controller -> localhost | |. = O+X S. | 2025-12-25 00:23:21.416552 | controller -> localhost | | = + X.+E | 2025-12-25 00:23:21.416599 | controller -> localhost | |o + o .+ | 2025-12-25 00:23:21.416640 | controller -> localhost | | + o . . | 2025-12-25 00:23:21.416710 | controller -> localhost | |... . | 2025-12-25 00:23:21.416767 | controller -> localhost | +----[SHA256]-----+ 2025-12-25 00:23:21.416863 | controller -> localhost | ok: Runtime: 0:00:00.317933 2025-12-25 00:23:21.431624 | 2025-12-25 00:23:21.431795 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-25 00:23:21.465426 | controller | ok 2025-12-25 00:23:21.475716 | controller | included: /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-25 00:23:21.485584 | 2025-12-25 00:23:21.485644 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-25 00:23:21.511394 | controller | skipping: Conditional result was False 2025-12-25 00:23:21.518785 | 2025-12-25 00:23:21.518851 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-25 00:23:21.953789 | controller | changed 2025-12-25 00:23:21.967239 | 2025-12-25 00:23:21.967402 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-25 00:23:22.191522 | controller | ok 2025-12-25 00:23:22.210989 | 2025-12-25 00:23:22.211163 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-25 00:23:22.843323 | controller | changed 2025-12-25 00:23:22.857473 | 2025-12-25 00:23:22.857822 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-25 00:23:23.519777 | controller | changed 2025-12-25 00:23:23.535417 | 2025-12-25 00:23:23.535603 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-25 00:23:23.586064 | controller | skipping: Conditional result was False 2025-12-25 00:23:23.622086 | 2025-12-25 00:23:23.622219 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-25 00:23:24.010848 | controller -> localhost | changed 2025-12-25 00:23:24.022951 | 2025-12-25 00:23:24.023029 | TASK [add-build-sshkey : Add back temp key] 2025-12-25 00:23:24.290276 | controller -> localhost | Identity added: /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/work/029dd6ceca1f45e48070167ca25d2919_id_rsa (zuul-build-sshkey) 2025-12-25 00:23:24.290500 | controller -> localhost | ok: Runtime: 0:00:00.008803 2025-12-25 00:23:24.297179 | 2025-12-25 00:23:24.297249 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-25 00:23:24.594441 | controller | ok 2025-12-25 00:23:24.607253 | 2025-12-25 00:23:24.607410 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-25 00:23:24.656450 | controller | skipping: Conditional result was False 2025-12-25 00:23:24.673221 | 2025-12-25 00:23:24.673342 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-25 00:23:24.707741 | controller | ok 2025-12-25 00:23:24.730619 | 2025-12-25 00:23:24.730764 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-25 00:23:25.016207 | controller -> localhost | ok 2025-12-25 00:23:25.022695 | 2025-12-25 00:23:25.022765 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-25 00:23:25.053635 | controller | ok 2025-12-25 00:23:25.069628 | controller | included: /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-25 00:23:25.075516 | 2025-12-25 00:23:25.075576 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-25 00:23:25.363798 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-25 00:23:25.364010 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/work/029dd6ceca1f45e48070167ca25d2919_id_ecdsa. 2025-12-25 00:23:25.364042 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/work/029dd6ceca1f45e48070167ca25d2919_id_ecdsa.pub. 2025-12-25 00:23:25.364073 | controller -> localhost | The key fingerprint is: 2025-12-25 00:23:25.364093 | controller -> localhost | SHA256:ENHV/FeLzumAdS0rRQZUM6DDhAPmUjF4jX9iCD+KGwk zuul-build-sshkey 2025-12-25 00:23:25.364112 | controller -> localhost | The key's randomart image is: 2025-12-25 00:23:25.364130 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-25 00:23:25.364147 | controller -> localhost | | .*Bo.oo*++ | 2025-12-25 00:23:25.364164 | controller -> localhost | | o+o.=+ . ooo .| 2025-12-25 00:23:25.364180 | controller -> localhost | | .+.+ .+ o.o o| 2025-12-25 00:23:25.364197 | controller -> localhost | |E .+ = ... =.o.| 2025-12-25 00:23:25.364214 | controller -> localhost | |. o . o S o = +. | 2025-12-25 00:23:25.364231 | controller -> localhost | | + . . o = | 2025-12-25 00:23:25.364247 | controller -> localhost | | o + | 2025-12-25 00:23:25.364264 | controller -> localhost | | . . | 2025-12-25 00:23:25.364281 | controller -> localhost | | | 2025-12-25 00:23:25.364297 | controller -> localhost | +----[SHA256]-----+ 2025-12-25 00:23:25.364350 | controller -> localhost | ok: Runtime: 0:00:00.016734 2025-12-25 00:23:25.371354 | 2025-12-25 00:23:25.371418 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-25 00:23:25.403056 | controller | ok 2025-12-25 00:23:25.410409 | controller | included: /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-25 00:23:25.418825 | 2025-12-25 00:23:25.418886 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-25 00:23:25.443743 | controller | skipping: Conditional result was False 2025-12-25 00:23:25.450470 | 2025-12-25 00:23:25.450537 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-25 00:23:25.727337 | controller | changed 2025-12-25 00:23:25.736559 | 2025-12-25 00:23:25.736648 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-25 00:23:25.970803 | controller | ok 2025-12-25 00:23:25.985034 | 2025-12-25 00:23:25.985243 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-25 00:23:26.676590 | controller | changed 2025-12-25 00:23:26.692389 | 2025-12-25 00:23:26.692533 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-25 00:23:27.329790 | controller | changed 2025-12-25 00:23:27.337788 | 2025-12-25 00:23:27.337873 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-25 00:23:27.365272 | controller | skipping: Conditional result was False 2025-12-25 00:23:27.374485 | 2025-12-25 00:23:27.374593 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-25 00:23:27.643915 | controller -> localhost | changed 2025-12-25 00:23:27.668249 | 2025-12-25 00:23:27.668542 | TASK [add-build-sshkey : Add back temp key] 2025-12-25 00:23:27.952359 | controller -> localhost | Identity added: /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/work/029dd6ceca1f45e48070167ca25d2919_id_ecdsa (zuul-build-sshkey) 2025-12-25 00:23:27.952638 | controller -> localhost | ok: Runtime: 0:00:00.013727 2025-12-25 00:23:27.961925 | 2025-12-25 00:23:27.962078 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-25 00:23:28.179618 | controller | ok 2025-12-25 00:23:28.187611 | 2025-12-25 00:23:28.187749 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-25 00:23:28.217588 | controller | skipping: Conditional result was False 2025-12-25 00:23:28.234006 | 2025-12-25 00:23:28.234111 | TASK [include_role : remove-zuul-sshkey] 2025-12-25 00:23:28.261519 | controller | skipping: Conditional result was False 2025-12-25 00:23:28.270234 | 2025-12-25 00:23:28.270323 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-25 00:23:28.530545 | controller | ok: "logs" 2025-12-25 00:23:28.530893 | controller | ok: All items complete 2025-12-25 00:23:28.530922 | 2025-12-25 00:23:28.728175 | controller | ok: "artifacts" 2025-12-25 00:23:28.924809 | controller | ok: "docs" 2025-12-25 00:23:28.939470 | 2025-12-25 00:23:28.939756 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-25 00:23:29.164176 | controller | changed: "logs" 2025-12-25 00:23:29.366741 | controller | changed: "artifacts" 2025-12-25 00:23:29.557146 | controller | changed: "docs" 2025-12-25 00:23:29.594250 | 2025-12-25 00:23:29.594376 | PLAY RECAP 2025-12-25 00:23:29.594425 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-25 00:23:29.594453 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-25 00:23:29.594472 | 2025-12-25 00:23:29.736654 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-25 00:23:29.738581 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-25 00:23:30.347953 | 2025-12-25 00:23:30.348124 | PLAY [all] 2025-12-25 00:23:30.375666 | 2025-12-25 00:23:30.375835 | TASK [Install binary dependencies] 2025-12-25 00:23:30.469572 | controller | ok 2025-12-25 00:23:30.491427 | 2025-12-25 00:23:30.491563 | TASK [bindep : Include find tasks] 2025-12-25 00:23:30.536093 | controller | ok 2025-12-25 00:23:30.545874 | controller | included: /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-25 00:23:30.555085 | 2025-12-25 00:23:30.555172 | TASK [bindep : Look for bindep.txt] 2025-12-25 00:23:30.944094 | controller | ok 2025-12-25 00:23:30.957959 | 2025-12-25 00:23:30.958124 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:23:30.986769 | controller | skipping: Conditional result was False 2025-12-25 00:23:31.000940 | 2025-12-25 00:23:31.001130 | TASK [bindep : Look for other-requirements.txt] 2025-12-25 00:23:31.224377 | controller | ok 2025-12-25 00:23:31.237318 | 2025-12-25 00:23:31.237467 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:23:31.264952 | controller | skipping: Conditional result was False 2025-12-25 00:23:31.280172 | 2025-12-25 00:23:31.280341 | TASK [bindep : Look for bindep fallback file] 2025-12-25 00:23:31.319236 | controller | skipping: Conditional result was False 2025-12-25 00:23:31.332558 | 2025-12-25 00:23:31.332813 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:23:31.369961 | controller | skipping: Conditional result was False 2025-12-25 00:23:31.380271 | 2025-12-25 00:23:31.380480 | TASK [bindep : Include bindep tasks] 2025-12-25 00:23:31.417081 | controller | skipping: Conditional result was False 2025-12-25 00:23:31.427170 | 2025-12-25 00:23:31.427338 | TASK [bindep : Include install tasks] 2025-12-25 00:23:31.453964 | controller | skipping: Conditional result was False 2025-12-25 00:23:31.466663 | 2025-12-25 00:23:31.466949 | LOOP [bindep : Include package tasks] 2025-12-25 00:23:31.533402 | 2025-12-25 00:23:31.533708 | TASK [Run test-setup role] 2025-12-25 00:23:31.560791 | controller | ok 2025-12-25 00:23:31.590571 | 2025-12-25 00:23:31.590795 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-25 00:23:31.804976 | controller | ok 2025-12-25 00:23:31.817442 | 2025-12-25 00:23:31.817617 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-25 00:23:32.379370 | controller | skipping: Conditional result was False 2025-12-25 00:23:32.439466 | 2025-12-25 00:23:32.439562 | PLAY RECAP 2025-12-25 00:23:32.439616 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-25 00:23:32.439644 | 2025-12-25 00:23:32.554224 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-25 00:23:32.556014 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-25 00:23:33.197493 | 2025-12-25 00:23:33.197745 | PLAY [controller] 2025-12-25 00:23:33.222487 | 2025-12-25 00:23:33.222736 | TASK [Create the /root directory] 2025-12-25 00:23:33.653771 | controller | ok 2025-12-25 00:23:33.670495 | 2025-12-25 00:23:33.670800 | TASK [Install glibc-langpack-en] 2025-12-25 00:23:37.638829 | controller | ok: Nothing to do 2025-12-25 00:23:37.657192 | 2025-12-25 00:23:37.657410 | TASK [Ensure controller directory exists] 2025-12-25 00:23:37.886667 | controller | changed 2025-12-25 00:23:37.903179 | 2025-12-25 00:23:37.903332 | TASK [Install container runtime] 2025-12-25 00:23:37.984604 | controller | ok 2025-12-25 00:23:38.045663 | 2025-12-25 00:23:38.045831 | LOOP [ensure-podman : Find distribution installation] 2025-12-25 00:23:38.106123 | controller | ok: "/var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-25 00:23:38.132159 | controller | included: /var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-25 00:23:38.146852 | 2025-12-25 00:23:38.147002 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-25 00:24:45.332920 | controller | changed 2025-12-25 00:24:45.347078 | 2025-12-25 00:24:45.347218 | TASK [ensure-podman : Fetch podman version] 2025-12-25 00:24:45.900193 | controller | Client: Podman Engine 2025-12-25 00:24:45.930469 | controller | Version: 4.6.2 2025-12-25 00:24:45.930494 | controller | API Version: 4.6.2 2025-12-25 00:24:45.930502 | controller | Go Version: go1.19.12 2025-12-25 00:24:45.930519 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-25 00:24:45.930526 | controller | OS/Arch: linux/amd64 2025-12-25 00:24:46.398249 | controller | ok: Runtime: 0:00:00.191886 2025-12-25 00:24:46.416105 | 2025-12-25 00:24:46.416303 | TASK [ensure-podman : Print podman version installed] 2025-12-25 00:24:46.457875 | Podman version: Client: Podman Engine 2025-12-25 00:24:46.458177 | Version: 4.6.2 2025-12-25 00:24:46.458241 | API Version: 4.6.2 2025-12-25 00:24:46.458287 | Go Version: go1.19.12 2025-12-25 00:24:46.458327 | Built: Mon Aug 28 19:38:31 2023 2025-12-25 00:24:46.458368 | OS/Arch: linux/amd64 2025-12-25 00:24:46.475825 | 2025-12-25 00:24:46.476049 | TASK [ensure-podman : Validate podman engine] 2025-12-25 00:24:47.050926 | controller | skipping: Conditional result was False 2025-12-25 00:24:47.059093 | 2025-12-25 00:24:47.059161 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-25 00:24:47.075356 | controller | skipping: Conditional result was False 2025-12-25 00:24:47.101547 | 2025-12-25 00:24:47.101739 | TASK [Ensure python3.8 is present] 2025-12-25 00:24:47.119929 | controller | skipping: Conditional result was False 2025-12-25 00:24:47.133796 | 2025-12-25 00:24:47.133936 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-25 00:24:47.163002 | controller | ok 2025-12-25 00:24:47.194529 | 2025-12-25 00:24:47.194636 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-25 00:24:48.803940 | controller | ok: Nothing to do 2025-12-25 00:24:48.813774 | 2025-12-25 00:24:48.813885 | TASK [our-ensure-python : Also install python3-devel] 2025-12-25 00:25:03.499480 | controller | changed 2025-12-25 00:25:03.527813 | 2025-12-25 00:25:03.527958 | TASK [Run ensure-virtualenv role] 2025-12-25 00:25:03.557733 | controller | ok 2025-12-25 00:25:03.592415 | 2025-12-25 00:25:03.592531 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-25 00:25:03.830472 | controller | /usr/bin/virtualenv 2025-12-25 00:25:04.159960 | controller | ok: Runtime: 0:00:00.004737 2025-12-25 00:25:04.168279 | 2025-12-25 00:25:04.168372 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-25 00:25:04.193349 | controller | skipping: Conditional result was False 2025-12-25 00:25:04.193653 | controller | ok: All items complete 2025-12-25 00:25:04.193773 | 2025-12-25 00:25:04.210633 | 2025-12-25 00:25:04.210824 | TASK [Find the full path of the Python interpreter] 2025-12-25 00:25:04.437299 | controller | /usr/bin/python3 2025-12-25 00:25:04.752346 | controller | ok 2025-12-25 00:25:04.760932 | 2025-12-25 00:25:04.761043 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-25 00:25:05.554026 | controller | created virtual environment CPython3.11.0.final.0-64 in 439ms 2025-12-25 00:25:05.580814 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-25 00:25:05.581160 | 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-25 00:25:05.581279 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-25 00:25:05.581495 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-25 00:25:05.802856 | controller | changed 2025-12-25 00:25:05.811481 | 2025-12-25 00:25:05.811564 | TASK [Set selinux package] 2025-12-25 00:25:05.852845 | controller | ok 2025-12-25 00:25:05.864250 | 2025-12-25 00:25:05.864379 | TASK [Set selinux package (Fedora)] 2025-12-25 00:25:05.910770 | controller | ok 2025-12-25 00:25:05.918876 | 2025-12-25 00:25:05.918967 | TASK [Install selinux into virtualenv] 2025-12-25 00:25:43.391196 | controller | Collecting selinux-please-lie-to-me 2025-12-25 00:25:55.648396 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-25 00:25:55.954149 | controller | Collecting setuptools<50.0.0 2025-12-25 00:25:55.959363 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-25 00:25:56.016378 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 15.4 MB/s eta 0:00:00 2025-12-25 00:25:56.096339 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-25 00:25:56.096500 | controller | Attempting uninstall: setuptools 2025-12-25 00:25:56.098872 | controller | Found existing installation: setuptools 62.6.0 2025-12-25 00:25:56.157229 | controller | Uninstalling setuptools-62.6.0: 2025-12-25 00:25:56.165229 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-25 00:25:56.537014 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-25 00:26:12.819780 | controller | 2025-12-25 00:26:12.904233 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-25 00:26:12.904274 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-25 00:26:12.994763 | controller | ok: Runtime: 0:01:06.742569 2025-12-25 00:26:13.008870 | 2025-12-25 00:26:13.009011 | TASK [Install pytest-forked into virtualenv] 2025-12-25 00:26:25.065325 | controller | Collecting pytest-forked 2025-12-25 00:26:37.312133 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-25 00:26:37.351913 | controller | Collecting py 2025-12-25 00:26:37.356948 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-25 00:26:37.380538 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 5.2 MB/s eta 0:00:00 2025-12-25 00:26:37.496100 | controller | Collecting pytest>=3.10 2025-12-25 00:26:37.500723 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-25 00:26:37.516986 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 29.1 MB/s eta 0:00:00 2025-12-25 00:26:37.561398 | controller | Collecting iniconfig>=1.0.1 2025-12-25 00:26:37.564788 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-25 00:26:37.613590 | controller | Collecting packaging>=22 2025-12-25 00:26:37.616826 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-25 00:26:37.626688 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.2 MB/s eta 0:00:00 2025-12-25 00:26:37.665395 | controller | Collecting pluggy<2,>=1.5 2025-12-25 00:26:37.668521 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-25 00:26:37.722234 | controller | Collecting pygments>=2.7.2 2025-12-25 00:26:37.726043 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-25 00:26:37.748794 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 67.2 MB/s eta 0:00:00 2025-12-25 00:26:37.819167 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-25 00:26:38.917301 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0 2025-12-25 00:26:38.926017 | controller | 2025-12-25 00:26:38.993920 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-25 00:26:38.993935 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-25 00:26:39.077382 | controller | ok: Runtime: 0:00:25.766579 2025-12-25 00:26:39.089504 | 2025-12-25 00:26:39.089650 | TASK [Update pip] 2025-12-25 00:26:39.674786 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-25 00:27:04.030768 | controller | Collecting pip 2025-12-25 00:27:16.221817 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-25 00:27:16.278997 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 34.9 MB/s eta 0:00:00 2025-12-25 00:27:16.343824 | controller | Installing collected packages: pip 2025-12-25 00:27:16.344045 | controller | Attempting uninstall: pip 2025-12-25 00:27:16.346235 | controller | Found existing installation: pip 22.2.2 2025-12-25 00:27:16.483055 | controller | Uninstalling pip-22.2.2: 2025-12-25 00:27:16.498487 | controller | Successfully uninstalled pip-22.2.2 2025-12-25 00:27:17.305801 | controller | Successfully installed pip-25.3 2025-12-25 00:27:17.695150 | controller | ok: Runtime: 0:00:37.992158 2025-12-25 00:27:17.703238 | 2025-12-25 00:27:17.703343 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-25 00:27:17.933652 | controller | changed 2025-12-25 00:27:17.941823 | 2025-12-25 00:27:17.941920 | TASK [Install ansible into virtualenv] 2025-12-25 00:27:18.447788 | controller | Processing ./src/github.com/ansible/ansible 2025-12-25 00:27:18.451047 | controller | Installing build dependencies: started 2025-12-25 00:27:53.138019 | controller | Installing build dependencies: finished with status 'done' 2025-12-25 00:27:53.138689 | controller | Getting requirements to build wheel: started 2025-12-25 00:27:53.881490 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-25 00:27:53.882788 | controller | Preparing metadata (pyproject.toml): started 2025-12-25 00:27:54.345267 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-25 00:27:54.350435 | 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-25 00:27:54.354163 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-25 00:27:54.502647 | controller | ERROR 2025-12-25 00:27:54.503042 | controller | { 2025-12-25 00:27:54.503104 | controller | "delta": "0:00:36.246485", 2025-12-25 00:27:54.503146 | controller | "end": "2025-12-25 00:27:54.415940", 2025-12-25 00:27:54.503184 | controller | "msg": "non-zero return code", 2025-12-25 00:27:54.503240 | controller | "rc": 1, 2025-12-25 00:27:54.503276 | controller | "start": "2025-12-25 00:27:18.169455" 2025-12-25 00:27:54.503309 | controller | } failure 2025-12-25 00:27:54.505993 | 2025-12-25 00:27:54.506085 | PLAY RECAP 2025-12-25 00:27:54.506166 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-25 00:27:54.506208 | 2025-12-25 00:27:54.659083 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-25 00:27:54.660106 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-25 00:27:55.325933 | 2025-12-25 00:27:55.326053 | PLAY [all] 2025-12-25 00:27:55.347052 | 2025-12-25 00:27:55.347139 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-25 00:27:55.607853 | controller | changed: non-zero return code 2025-12-25 00:27:55.630312 | 2025-12-25 00:27:55.630418 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-25 00:27:55.646608 | controller | skipping: Conditional result was False 2025-12-25 00:27:55.654736 | 2025-12-25 00:27:55.654834 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-25 00:27:55.685836 | 2025-12-25 00:27:55.685980 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-25 00:27:55.716193 | 2025-12-25 00:27:55.716318 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-25 00:27:55.740831 | controller | skipping: Conditional result was False 2025-12-25 00:27:55.748181 | 2025-12-25 00:27:55.748252 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-25 00:27:55.779379 | 2025-12-25 00:27:55.779564 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-25 00:27:55.794132 | controller | skipping: Conditional result was False 2025-12-25 00:27:55.800844 | 2025-12-25 00:27:55.800923 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-25 00:27:55.815053 | controller | skipping: Conditional result was False 2025-12-25 00:27:55.821699 | 2025-12-25 00:27:55.821773 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-25 00:27:55.836051 | controller | skipping: Conditional result was False 2025-12-25 00:27:55.862212 | 2025-12-25 00:27:55.862268 | PLAY RECAP 2025-12-25 00:27:55.862307 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-25 00:27:55.862327 | 2025-12-25 00:27:55.958625 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-25 00:27:55.960431 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-25 00:27:56.636380 | 2025-12-25 00:27:56.636509 | PLAY [all:!appliance*] 2025-12-25 00:27:56.660301 | 2025-12-25 00:27:56.660410 | TASK [unregister the node] 2025-12-25 00:27:57.191824 | controller | skipping: Conditional result was False 2025-12-25 00:27:57.207263 | 2025-12-25 00:27:57.207456 | TASK [include_role : fetch-output] 2025-12-25 00:27:57.257971 | controller | ok 2025-12-25 00:27:57.299421 | 2025-12-25 00:27:57.299550 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-25 00:27:57.345618 | controller | skipping: Conditional result was False 2025-12-25 00:27:57.361310 | 2025-12-25 00:27:57.361491 | TASK [fetch-output : Set log path for single node] 2025-12-25 00:27:57.404153 | controller | ok 2025-12-25 00:27:57.420245 | 2025-12-25 00:27:57.420418 | LOOP [fetch-output : Ensure local output dirs] 2025-12-25 00:27:57.863611 | controller -> localhost | ok: "/var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/work/logs" 2025-12-25 00:27:58.143025 | controller -> localhost | changed: "/var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/work/artifacts" 2025-12-25 00:27:58.374731 | controller -> localhost | changed: "/var/lib/zuul/builds/029dd6ceca1f45e48070167ca25d2919/work/docs" 2025-12-25 00:27:58.393306 | 2025-12-25 00:27:58.393484 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-25 00:27:59.119479 | controller | changed: 2025-12-25 00:27:59.119865 | controller | .d..t...... ./ 2025-12-25 00:27:59.119931 | controller | cd+++++++++ controller/ 2025-12-25 00:27:59.120005 | controller | changed: All items complete 2025-12-25 00:27:59.120054 | 2025-12-25 00:27:59.689570 | controller | changed: .d..t...... ./ 2025-12-25 00:28:00.217203 | controller | changed: .d..t...... ./ 2025-12-25 00:28:00.250248 | 2025-12-25 00:28:00.250445 | TASK [include_role : fetch-output-openshift] 2025-12-25 00:28:00.277351 | controller | skipping: Conditional result was False 2025-12-25 00:28:00.286318 | 2025-12-25 00:28:00.286408 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-25 00:28:00.332061 | controller | skipping: Conditional result was False 2025-12-25 00:28:00.344139 | controller | skipping: Conditional result was False 2025-12-25 00:28:00.406078 | 2025-12-25 00:28:00.406191 | PLAY [localhost] 2025-12-25 00:28:00.422956 | 2025-12-25 00:28:00.423034 | TASK [Run Zuul manifest role] 2025-12-25 00:28:00.444056 | localhost | ok 2025-12-25 00:28:00.462415 | 2025-12-25 00:28:00.462504 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-25 00:28:00.919190 | localhost | changed 2025-12-25 00:28:00.923956 | 2025-12-25 00:28:00.924018 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-25 00:28:00.964163 | localhost | ok 2025-12-25 00:28:00.972362 | 2025-12-25 00:28:00.972422 | TASK [Set zuul-log-path fact] 2025-12-25 00:28:00.991028 | localhost | ok 2025-12-25 00:28:01.004986 | 2025-12-25 00:28:01.005062 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-25 00:28:01.043977 | localhost | ok 2025-12-25 00:28:01.052638 | 2025-12-25 00:28:01.052718 | LOOP [Run upload-logs-swift role] 2025-12-25 00:28:01.099537 | localhost | Output suppressed because no_log was given 2025-12-25 00:28:01.142471 | 2025-12-25 00:28:01.142629 | TASK [Set zuul-log-path fact] 2025-12-25 00:28:01.168292 | localhost | skipping: Conditional result was False 2025-12-25 00:28:01.175898 | 2025-12-25 00:28:01.175995 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-25 00:28:01.645528 | localhost -> localhost | ok: Runtime: 0:00:00.007759 2025-12-25 00:28:01.679835 | 2025-12-25 00:28:01.679987 | TASK [upload-logs-swift : Upload logs to swift]