2025-12-03 00:25:14.973901 | Job console starting... 2025-12-03 00:25:14.984288 | Updating repositories 2025-12-03 00:25:15.136019 | Preparing job workspace 2025-12-03 00:25:19.167280 | Running Ansible setup... 2025-12-03 00:25:23.949802 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-03 00:25:24.492105 | 2025-12-03 00:25:24.492216 | PLAY [localhost] 2025-12-03 00:25:24.500307 | 2025-12-03 00:25:24.500400 | TASK [Gathering Facts] 2025-12-03 00:25:25.503184 | localhost | ok 2025-12-03 00:25:25.536255 | 2025-12-03 00:25:25.536398 | TASK [Setup log path fact] 2025-12-03 00:25:25.557244 | localhost | ok 2025-12-03 00:25:25.572646 | 2025-12-03 00:25:25.572728 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-03 00:25:25.600274 | localhost | ok 2025-12-03 00:25:25.608118 | 2025-12-03 00:25:25.608187 | TASK [emit-job-header : Print job information] 2025-12-03 00:25:25.655887 | # Job Information 2025-12-03 00:25:25.655995 | Ansible Version: 2.15.12 2025-12-03 00:25:25.656025 | Job: ansible-test-sanity-docker-devel 2025-12-03 00:25:25.656046 | Pipeline: periodic 2025-12-03 00:25:25.656064 | Executor: ze04.softwarefactory-project.io 2025-12-03 00:25:25.656082 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-03 00:25:25.656102 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/fc0/ansible/fc05a287b3e74fb38d9c3d48f6b9404d/ 2025-12-03 00:25:25.656121 | Event ID: 08d03c5eb6c54d3f91ad96751eb57522 2025-12-03 00:25:25.659729 | 2025-12-03 00:25:25.659789 | LOOP [emit-job-header : Print node information] 2025-12-03 00:25:25.764373 | localhost | ok: 2025-12-03 00:25:25.764543 | localhost | # Node Information 2025-12-03 00:25:25.764572 | localhost | Inventory Hostname: controller 2025-12-03 00:25:25.764594 | localhost | Hostname: np0005543041 2025-12-03 00:25:25.764614 | localhost | Username: zuul 2025-12-03 00:25:25.764638 | localhost | Distro: Fedora 37 2025-12-03 00:25:25.764657 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-03 00:25:25.764692 | localhost | Region: ca-ymq-1 2025-12-03 00:25:25.764716 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-03 00:25:25.764734 | localhost | Product Name: OpenStack Nova 2025-12-03 00:25:25.764752 | localhost | Interface IP: 162.253.55.204 2025-12-03 00:25:25.778978 | 2025-12-03 00:25:25.779152 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-03 00:25:26.168514 | localhost -> localhost | changed 2025-12-03 00:25:26.182256 | 2025-12-03 00:25:26.182359 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-03 00:25:27.082056 | localhost -> localhost | changed 2025-12-03 00:25:27.124476 | 2025-12-03 00:25:27.124630 | PLAY [all:!appliance*] 2025-12-03 00:25:27.147026 | 2025-12-03 00:25:27.147158 | TASK [include_role : start-zuul-console] 2025-12-03 00:25:27.169463 | controller | ok 2025-12-03 00:25:27.188185 | 2025-12-03 00:25:27.188295 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-03 00:25:27.576780 | controller | ok 2025-12-03 00:25:27.600824 | 2025-12-03 00:25:27.600932 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-03 00:25:28.768314 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-03 00:25:28.781890 | 2025-12-03 00:25:28.782020 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-03 00:25:29.341123 | controller | skipping: Conditional result was False 2025-12-03 00:25:29.349964 | 2025-12-03 00:25:29.350060 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-03 00:25:29.376002 | controller | skipping: Conditional result was False 2025-12-03 00:25:29.386770 | 2025-12-03 00:25:29.386932 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-03 00:25:29.417193 | controller | skipping: Conditional result was False 2025-12-03 00:25:29.427060 | 2025-12-03 00:25:29.427237 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-03 00:25:29.457388 | controller | skipping: Conditional result was False 2025-12-03 00:25:29.469616 | 2025-12-03 00:25:29.469810 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-03 00:25:29.495544 | controller | skipping: Conditional result was False 2025-12-03 00:25:29.506916 | 2025-12-03 00:25:29.507050 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-03 00:25:29.533063 | controller | skipping: Conditional result was False 2025-12-03 00:25:29.552818 | 2025-12-03 00:25:29.552967 | TASK [Disable Fedora Modular] 2025-12-03 00:25:29.809855 | controller | changed 2025-12-03 00:25:29.822637 | 2025-12-03 00:25:29.822814 | TASK [Enable EPEL] 2025-12-03 00:25:29.849359 | controller | skipping: Conditional result was False 2025-12-03 00:25:29.862878 | 2025-12-03 00:25:29.863020 | TASK [Register the RHEL node] 2025-12-03 00:25:30.418598 | 2025-12-03 00:25:30.418769 | TASK [Show the subscription-manager status] 2025-12-03 00:25:30.979283 | controller | skipping: Conditional result was False 2025-12-03 00:25:30.993272 | 2025-12-03 00:25:30.993441 | TASK [Enable EPEL on RHEL] 2025-12-03 00:25:31.549920 | controller | skipping: Conditional result was False 2025-12-03 00:25:31.563032 | 2025-12-03 00:25:31.563205 | TASK [Install git and tox] 2025-12-03 00:26:48.160729 | controller | changed 2025-12-03 00:26:48.174302 | 2025-12-03 00:26:48.174461 | TASK [include_role : prepare-workspace] 2025-12-03 00:26:48.214873 | controller | ok 2025-12-03 00:26:48.251532 | 2025-12-03 00:26:48.251710 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-03 00:26:48.503045 | controller | ok 2025-12-03 00:26:48.516946 | 2025-12-03 00:26:48.517114 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-03 00:27:00.784663 | controller | Output suppressed because no_log was given 2025-12-03 00:27:00.805788 | 2025-12-03 00:27:00.805981 | TASK [include_role : prepare-workspace-openshift] 2025-12-03 00:27:00.834312 | controller | skipping: Conditional result was False 2025-12-03 00:27:00.877813 | 2025-12-03 00:27:00.877888 | PLAY [all:!appliance] 2025-12-03 00:27:00.900925 | 2025-12-03 00:27:00.901014 | TASK [Run add-build-sshkey role (RSA)] 2025-12-03 00:27:00.934181 | controller | ok 2025-12-03 00:27:00.954907 | 2025-12-03 00:27:00.955003 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-03 00:27:01.219538 | controller -> localhost | ok 2025-12-03 00:27:01.230010 | 2025-12-03 00:27:01.230162 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-03 00:27:01.276805 | controller | ok 2025-12-03 00:27:01.306164 | controller | included: /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-03 00:27:01.312214 | 2025-12-03 00:27:01.312289 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-03 00:27:01.847761 | controller -> localhost | Generating public/private rsa key pair. 2025-12-03 00:27:01.848025 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/work/fc05a287b3e74fb38d9c3d48f6b9404d_id_rsa. 2025-12-03 00:27:01.848066 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/work/fc05a287b3e74fb38d9c3d48f6b9404d_id_rsa.pub. 2025-12-03 00:27:01.848096 | controller -> localhost | The key fingerprint is: 2025-12-03 00:27:01.848124 | controller -> localhost | SHA256:ah+08g2fUS+RtbLCNIxlvqvsNBvHRN+DpPHAmAPk0m8 zuul-build-sshkey 2025-12-03 00:27:01.848151 | controller -> localhost | The key's randomart image is: 2025-12-03 00:27:01.848177 | controller -> localhost | +---[RSA 2048]----+ 2025-12-03 00:27:01.848203 | controller -> localhost | | .o | 2025-12-03 00:27:01.848231 | controller -> localhost | | o . + | 2025-12-03 00:27:01.848256 | controller -> localhost | | . o + B . . | 2025-12-03 00:27:01.848281 | controller -> localhost | | . . O B = . | 2025-12-03 00:27:01.848306 | controller -> localhost | | E B O + | 2025-12-03 00:27:01.848343 | controller -> localhost | | + * + = . | 2025-12-03 00:27:01.848373 | controller -> localhost | | + B B o . | 2025-12-03 00:27:01.848400 | controller -> localhost | | . * X = . | 2025-12-03 00:27:01.848427 | controller -> localhost | | .B.= | 2025-12-03 00:27:01.848455 | controller -> localhost | +----[SHA256]-----+ 2025-12-03 00:27:01.848516 | controller -> localhost | ok: Runtime: 0:00:00.148268 2025-12-03 00:27:01.867377 | 2025-12-03 00:27:01.867523 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-03 00:27:01.898269 | controller | ok 2025-12-03 00:27:01.909781 | controller | included: /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-03 00:27:01.919704 | 2025-12-03 00:27:01.919803 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-03 00:27:01.943617 | controller | skipping: Conditional result was False 2025-12-03 00:27:01.950239 | 2025-12-03 00:27:01.950307 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-03 00:27:02.377183 | controller | changed 2025-12-03 00:27:02.383479 | 2025-12-03 00:27:02.383549 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-03 00:27:02.607902 | controller | ok 2025-12-03 00:27:02.614269 | 2025-12-03 00:27:02.614353 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-03 00:27:03.193917 | controller | changed 2025-12-03 00:27:03.204727 | 2025-12-03 00:27:03.204827 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-03 00:27:03.786397 | controller | changed 2025-12-03 00:27:03.792196 | 2025-12-03 00:27:03.792262 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-03 00:27:03.806095 | controller | skipping: Conditional result was False 2025-12-03 00:27:03.812961 | 2025-12-03 00:27:03.813054 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-03 00:27:04.181998 | controller -> localhost | changed 2025-12-03 00:27:04.195161 | 2025-12-03 00:27:04.195252 | TASK [add-build-sshkey : Add back temp key] 2025-12-03 00:27:04.505449 | controller -> localhost | Identity added: /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/work/fc05a287b3e74fb38d9c3d48f6b9404d_id_rsa (zuul-build-sshkey) 2025-12-03 00:27:04.505624 | controller -> localhost | ok: Runtime: 0:00:00.007566 2025-12-03 00:27:04.512213 | 2025-12-03 00:27:04.512281 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-03 00:27:04.848724 | controller | ok 2025-12-03 00:27:04.855999 | 2025-12-03 00:27:04.856084 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-03 00:27:04.881214 | controller | skipping: Conditional result was False 2025-12-03 00:27:04.893286 | 2025-12-03 00:27:04.893373 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-03 00:27:04.923293 | controller | ok 2025-12-03 00:27:04.939364 | 2025-12-03 00:27:04.939446 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-03 00:27:05.167124 | controller -> localhost | ok 2025-12-03 00:27:05.173360 | 2025-12-03 00:27:05.173446 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-03 00:27:05.212805 | controller | ok 2025-12-03 00:27:05.229732 | controller | included: /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-03 00:27:05.237207 | 2025-12-03 00:27:05.237277 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-03 00:27:05.506423 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-03 00:27:05.506627 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/work/fc05a287b3e74fb38d9c3d48f6b9404d_id_ecdsa. 2025-12-03 00:27:05.506657 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/work/fc05a287b3e74fb38d9c3d48f6b9404d_id_ecdsa.pub. 2025-12-03 00:27:05.506703 | controller -> localhost | The key fingerprint is: 2025-12-03 00:27:05.506728 | controller -> localhost | SHA256:5mXCthTSJVovRQNNddE6NfvqVVcUNdvGG+9t8Q3TE8U zuul-build-sshkey 2025-12-03 00:27:05.506749 | controller -> localhost | The key's randomart image is: 2025-12-03 00:27:05.506768 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-03 00:27:05.506786 | controller -> localhost | | +=*.. o**| 2025-12-03 00:27:05.506805 | controller -> localhost | | + =.. . +E| 2025-12-03 00:27:05.506822 | controller -> localhost | | o + . *B| 2025-12-03 00:27:05.506840 | controller -> localhost | | o o o+*| 2025-12-03 00:27:05.506857 | controller -> localhost | | S o o=*| 2025-12-03 00:27:05.506874 | controller -> localhost | | = = +X| 2025-12-03 00:27:05.506890 | controller -> localhost | | o .B| 2025-12-03 00:27:05.506907 | controller -> localhost | | .o | 2025-12-03 00:27:05.506924 | controller -> localhost | | .. | 2025-12-03 00:27:05.506941 | controller -> localhost | +----[SHA256]-----+ 2025-12-03 00:27:05.506992 | controller -> localhost | ok: Runtime: 0:00:00.010502 2025-12-03 00:27:05.518549 | 2025-12-03 00:27:05.518631 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-03 00:27:05.549335 | controller | ok 2025-12-03 00:27:05.557475 | controller | included: /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-03 00:27:05.569110 | 2025-12-03 00:27:05.569182 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-03 00:27:05.593839 | controller | skipping: Conditional result was False 2025-12-03 00:27:05.600239 | 2025-12-03 00:27:05.600303 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-03 00:27:05.879589 | controller | changed 2025-12-03 00:27:05.892319 | 2025-12-03 00:27:05.892456 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-03 00:27:06.123851 | controller | ok 2025-12-03 00:27:06.146080 | 2025-12-03 00:27:06.146281 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-03 00:27:06.739403 | controller | changed 2025-12-03 00:27:06.753284 | 2025-12-03 00:27:06.753441 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-03 00:27:07.399966 | controller | changed 2025-12-03 00:27:07.415369 | 2025-12-03 00:27:07.415515 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-03 00:27:07.442420 | controller | skipping: Conditional result was False 2025-12-03 00:27:07.454492 | 2025-12-03 00:27:07.454620 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-03 00:27:07.699021 | controller -> localhost | changed 2025-12-03 00:27:07.738261 | 2025-12-03 00:27:07.738374 | TASK [add-build-sshkey : Add back temp key] 2025-12-03 00:27:08.030905 | controller -> localhost | Identity added: /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/work/fc05a287b3e74fb38d9c3d48f6b9404d_id_ecdsa (zuul-build-sshkey) 2025-12-03 00:27:08.031101 | controller -> localhost | ok: Runtime: 0:00:00.007517 2025-12-03 00:27:08.037305 | 2025-12-03 00:27:08.037365 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-03 00:27:08.228757 | controller | ok 2025-12-03 00:27:08.241348 | 2025-12-03 00:27:08.241514 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-03 00:27:08.279821 | controller | skipping: Conditional result was False 2025-12-03 00:27:08.308122 | 2025-12-03 00:27:08.308267 | TASK [include_role : remove-zuul-sshkey] 2025-12-03 00:27:08.334695 | controller | skipping: Conditional result was False 2025-12-03 00:27:08.346907 | 2025-12-03 00:27:08.346995 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-03 00:27:08.582980 | controller | ok: "logs" 2025-12-03 00:27:08.583579 | controller | ok: All items complete 2025-12-03 00:27:08.583648 | 2025-12-03 00:27:08.768794 | controller | ok: "artifacts" 2025-12-03 00:27:08.960839 | controller | ok: "docs" 2025-12-03 00:27:08.978074 | 2025-12-03 00:27:08.978278 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-03 00:27:09.232385 | controller | changed: "logs" 2025-12-03 00:27:09.410642 | controller | changed: "artifacts" 2025-12-03 00:27:09.605338 | controller | changed: "docs" 2025-12-03 00:27:09.665653 | 2025-12-03 00:27:09.665816 | PLAY RECAP 2025-12-03 00:27:09.665873 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-03 00:27:09.665909 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-03 00:27:09.665933 | 2025-12-03 00:27:09.790845 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-03 00:27:09.791743 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-03 00:27:10.363392 | 2025-12-03 00:27:10.363493 | PLAY [all] 2025-12-03 00:27:10.385342 | 2025-12-03 00:27:10.385432 | TASK [Install binary dependencies] 2025-12-03 00:27:10.438376 | controller | ok 2025-12-03 00:27:10.458027 | 2025-12-03 00:27:10.458129 | TASK [bindep : Include find tasks] 2025-12-03 00:27:10.499294 | controller | ok 2025-12-03 00:27:10.507855 | controller | included: /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-03 00:27:10.513997 | 2025-12-03 00:27:10.514451 | TASK [bindep : Look for bindep.txt] 2025-12-03 00:27:10.853160 | controller | ok 2025-12-03 00:27:10.864105 | 2025-12-03 00:27:10.864255 | TASK [bindep : Define bindep_file fact] 2025-12-03 00:27:10.890357 | controller | skipping: Conditional result was False 2025-12-03 00:27:10.897489 | 2025-12-03 00:27:10.897642 | TASK [bindep : Look for other-requirements.txt] 2025-12-03 00:27:11.125185 | controller | ok 2025-12-03 00:27:11.133097 | 2025-12-03 00:27:11.133177 | TASK [bindep : Define bindep_file fact] 2025-12-03 00:27:11.180341 | controller | skipping: Conditional result was False 2025-12-03 00:27:11.192184 | 2025-12-03 00:27:11.192290 | TASK [bindep : Look for bindep fallback file] 2025-12-03 00:27:11.230364 | controller | skipping: Conditional result was False 2025-12-03 00:27:11.241381 | 2025-12-03 00:27:11.241473 | TASK [bindep : Define bindep_file fact] 2025-12-03 00:27:11.266082 | controller | skipping: Conditional result was False 2025-12-03 00:27:11.276820 | 2025-12-03 00:27:11.276932 | TASK [bindep : Include bindep tasks] 2025-12-03 00:27:11.303842 | controller | skipping: Conditional result was False 2025-12-03 00:27:11.310913 | 2025-12-03 00:27:11.311009 | TASK [bindep : Include install tasks] 2025-12-03 00:27:11.335582 | controller | skipping: Conditional result was False 2025-12-03 00:27:11.341834 | 2025-12-03 00:27:11.341907 | LOOP [bindep : Include package tasks] 2025-12-03 00:27:11.397642 | 2025-12-03 00:27:11.397814 | TASK [Run test-setup role] 2025-12-03 00:27:11.419438 | controller | ok 2025-12-03 00:27:11.439460 | 2025-12-03 00:27:11.439576 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-03 00:27:11.676288 | controller | ok 2025-12-03 00:27:11.685161 | 2025-12-03 00:27:11.685250 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-03 00:27:12.223840 | controller | skipping: Conditional result was False 2025-12-03 00:27:12.255827 | 2025-12-03 00:27:12.255933 | PLAY RECAP 2025-12-03 00:27:12.255975 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-03 00:27:12.255995 | 2025-12-03 00:27:12.377741 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-03 00:27:12.378587 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-03 00:27:12.968065 | 2025-12-03 00:27:12.968200 | PLAY [controller] 2025-12-03 00:27:12.989920 | 2025-12-03 00:27:12.990026 | TASK [Create the /root directory] 2025-12-03 00:27:13.346564 | controller | ok 2025-12-03 00:27:13.353003 | 2025-12-03 00:27:13.353077 | TASK [Install glibc-langpack-en] 2025-12-03 00:27:17.294942 | controller | ok: Nothing to do 2025-12-03 00:27:17.315794 | 2025-12-03 00:27:17.316014 | TASK [Ensure controller directory exists] 2025-12-03 00:27:17.544552 | controller | changed 2025-12-03 00:27:17.552667 | 2025-12-03 00:27:17.552792 | TASK [Install container runtime] 2025-12-03 00:27:17.628064 | controller | ok 2025-12-03 00:27:17.697814 | 2025-12-03 00:27:17.698024 | LOOP [ensure-podman : Find distribution installation] 2025-12-03 00:27:17.736506 | controller | ok: "/var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-03 00:27:17.753918 | controller | included: /var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-03 00:27:17.762804 | 2025-12-03 00:27:17.762900 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-03 00:28:22.684860 | controller | changed 2025-12-03 00:28:22.695104 | 2025-12-03 00:28:22.695220 | TASK [ensure-podman : Fetch podman version] 2025-12-03 00:28:23.202725 | controller | Client: Podman Engine 2025-12-03 00:28:23.228256 | controller | Version: 4.6.2 2025-12-03 00:28:23.228290 | controller | API Version: 4.6.2 2025-12-03 00:28:23.228303 | controller | Go Version: go1.19.12 2025-12-03 00:28:23.228329 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-03 00:28:23.228340 | controller | OS/Arch: linux/amd64 2025-12-03 00:28:23.269608 | controller | ok: Runtime: 0:00:00.178769 2025-12-03 00:28:23.285777 | 2025-12-03 00:28:23.285977 | TASK [ensure-podman : Print podman version installed] 2025-12-03 00:28:23.331671 | Podman version: Client: Podman Engine 2025-12-03 00:28:23.332068 | Version: 4.6.2 2025-12-03 00:28:23.332185 | API Version: 4.6.2 2025-12-03 00:28:23.332253 | Go Version: go1.19.12 2025-12-03 00:28:23.332300 | Built: Mon Aug 28 19:38:31 2023 2025-12-03 00:28:23.332349 | OS/Arch: linux/amd64 2025-12-03 00:28:23.346831 | 2025-12-03 00:28:23.347023 | TASK [ensure-podman : Validate podman engine] 2025-12-03 00:28:23.892739 | controller | skipping: Conditional result was False 2025-12-03 00:28:23.899623 | 2025-12-03 00:28:23.899744 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-03 00:28:23.924037 | controller | skipping: Conditional result was False 2025-12-03 00:28:23.951911 | 2025-12-03 00:28:23.952110 | TASK [Ensure python3.8 is present] 2025-12-03 00:28:23.978452 | controller | skipping: Conditional result was False 2025-12-03 00:28:23.987669 | 2025-12-03 00:28:23.987804 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-03 00:28:24.014885 | controller | ok 2025-12-03 00:28:24.040261 | 2025-12-03 00:28:24.040359 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-03 00:28:25.401165 | controller | ok: Nothing to do 2025-12-03 00:28:25.414266 | 2025-12-03 00:28:25.414434 | TASK [our-ensure-python : Also install python3-devel] 2025-12-03 00:28:34.256395 | controller | changed 2025-12-03 00:28:34.279845 | 2025-12-03 00:28:34.279990 | TASK [Run ensure-virtualenv role] 2025-12-03 00:28:34.305911 | controller | ok 2025-12-03 00:28:34.339589 | 2025-12-03 00:28:34.339808 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-03 00:28:34.553200 | controller | /usr/bin/virtualenv 2025-12-03 00:28:34.876323 | controller | ok: Runtime: 0:00:00.004819 2025-12-03 00:28:34.882870 | 2025-12-03 00:28:34.882936 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-03 00:28:34.901000 | controller | skipping: Conditional result was False 2025-12-03 00:28:34.901429 | controller | ok: All items complete 2025-12-03 00:28:34.901488 | 2025-12-03 00:28:34.935132 | 2025-12-03 00:28:34.935352 | TASK [Find the full path of the Python interpreter] 2025-12-03 00:28:35.196103 | controller | /usr/bin/python3 2025-12-03 00:28:35.523038 | controller | ok 2025-12-03 00:28:35.535723 | 2025-12-03 00:28:35.535859 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-03 00:28:36.507291 | controller | created virtual environment CPython3.11.0.final.0-64 in 566ms 2025-12-03 00:28:36.528057 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-03 00:28:36.528422 | 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-03 00:28:36.528651 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-03 00:28:36.529013 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-03 00:28:36.592802 | controller | changed 2025-12-03 00:28:36.613938 | 2025-12-03 00:28:36.614120 | TASK [Set selinux package] 2025-12-03 00:28:36.652274 | controller | ok 2025-12-03 00:28:36.659862 | 2025-12-03 00:28:36.659950 | TASK [Set selinux package (Fedora)] 2025-12-03 00:28:36.713241 | controller | ok 2025-12-03 00:28:36.720822 | 2025-12-03 00:28:36.720909 | TASK [Install selinux into virtualenv] 2025-12-03 00:28:50.253218 | controller | Collecting selinux-please-lie-to-me 2025-12-03 00:29:02.526774 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-03 00:29:02.845523 | controller | Collecting setuptools<50.0.0 2025-12-03 00:29:02.855401 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-03 00:29:02.897372 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.3 MB/s eta 0:00:00 2025-12-03 00:29:02.979055 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-03 00:29:02.979277 | controller | Attempting uninstall: setuptools 2025-12-03 00:29:02.981686 | controller | Found existing installation: setuptools 62.6.0 2025-12-03 00:29:03.041800 | controller | Uninstalling setuptools-62.6.0: 2025-12-03 00:29:03.050122 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-03 00:29:03.398276 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-03 00:29:14.869512 | controller | 2025-12-03 00:29:14.950705 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-03 00:29:14.950764 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-03 00:29:15.302051 | controller | ok: Runtime: 0:00:37.999563 2025-12-03 00:29:15.315088 | 2025-12-03 00:29:15.315238 | TASK [Install pytest-forked into virtualenv] 2025-12-03 00:29:27.141179 | controller | Collecting pytest-forked 2025-12-03 00:29:37.316588 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-03 00:29:37.363757 | controller | Collecting py 2025-12-03 00:29:37.368012 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-03 00:29:37.391423 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.5 MB/s eta 0:00:00 2025-12-03 00:29:37.502350 | controller | Collecting pytest>=3.10 2025-12-03 00:29:37.505946 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-12-03 00:29:37.525264 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 22.3 MB/s eta 0:00:00 2025-12-03 00:29:37.564871 | controller | Collecting iniconfig>=1.0.1 2025-12-03 00:29:37.568417 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-03 00:29:37.619461 | controller | Collecting packaging>=22 2025-12-03 00:29:37.622673 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-03 00:29:37.630463 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.8 MB/s eta 0:00:00 2025-12-03 00:29:37.670734 | controller | Collecting pluggy<2,>=1.5 2025-12-03 00:29:37.674225 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-03 00:29:37.723295 | controller | Collecting pygments>=2.7.2 2025-12-03 00:29:37.726937 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-03 00:29:37.755194 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 49.6 MB/s eta 0:00:00 2025-12-03 00:29:37.828887 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-03 00:29:38.898972 | 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-03 00:29:38.908230 | controller | 2025-12-03 00:29:38.983010 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-03 00:29:38.983040 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-03 00:29:39.390351 | controller | ok: Runtime: 0:00:23.437933 2025-12-03 00:29:39.404960 | 2025-12-03 00:29:39.405145 | TASK [Update pip] 2025-12-03 00:29:39.930284 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-03 00:29:49.697690 | controller | Collecting pip 2025-12-03 00:30:01.886388 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-03 00:30:01.945090 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 33.3 MB/s eta 0:00:00 2025-12-03 00:30:02.009070 | controller | Installing collected packages: pip 2025-12-03 00:30:02.009251 | controller | Attempting uninstall: pip 2025-12-03 00:30:02.011365 | controller | Found existing installation: pip 22.2.2 2025-12-03 00:30:02.149234 | controller | Uninstalling pip-22.2.2: 2025-12-03 00:30:02.166297 | controller | Successfully uninstalled pip-22.2.2 2025-12-03 00:30:02.957356 | controller | Successfully installed pip-25.3 2025-12-03 00:30:03.465535 | controller | ok: Runtime: 0:00:23.394520 2025-12-03 00:30:03.480304 | 2025-12-03 00:30:03.480588 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-03 00:30:03.718775 | controller | changed 2025-12-03 00:30:03.726318 | 2025-12-03 00:30:03.726400 | TASK [Install ansible into virtualenv] 2025-12-03 00:30:04.243622 | controller | Processing ./src/github.com/ansible/ansible 2025-12-03 00:30:04.247065 | controller | Installing build dependencies: started 2025-12-03 00:30:26.850020 | controller | Installing build dependencies: finished with status 'done' 2025-12-03 00:30:26.851406 | controller | Getting requirements to build wheel: started 2025-12-03 00:30:27.630896 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-03 00:30:27.632096 | controller | Preparing metadata (pyproject.toml): started 2025-12-03 00:30:28.120710 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-03 00:30:28.125686 | 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-03 00:30:28.129740 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-03 00:30:28.280735 | controller | ERROR 2025-12-03 00:30:28.280983 | controller | { 2025-12-03 00:30:28.281022 | controller | "delta": "0:00:24.251389", 2025-12-03 00:30:28.281048 | controller | "end": "2025-12-03 00:30:28.209315", 2025-12-03 00:30:28.281071 | controller | "msg": "non-zero return code", 2025-12-03 00:30:28.281109 | controller | "rc": 1, 2025-12-03 00:30:28.281132 | controller | "start": "2025-12-03 00:30:03.957926" 2025-12-03 00:30:28.281153 | controller | } failure 2025-12-03 00:30:28.283364 | 2025-12-03 00:30:28.283436 | PLAY RECAP 2025-12-03 00:30:28.283497 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-03 00:30:28.283528 | 2025-12-03 00:30:28.418514 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-03 00:30:28.420473 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-03 00:30:29.032669 | 2025-12-03 00:30:29.032823 | PLAY [all] 2025-12-03 00:30:29.056246 | 2025-12-03 00:30:29.056376 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-03 00:30:29.350403 | controller | changed: non-zero return code 2025-12-03 00:30:29.363568 | 2025-12-03 00:30:29.363778 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-03 00:30:29.391260 | controller | skipping: Conditional result was False 2025-12-03 00:30:29.419295 | 2025-12-03 00:30:29.419443 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-03 00:30:29.456575 | 2025-12-03 00:30:29.456804 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-03 00:30:29.488873 | 2025-12-03 00:30:29.489028 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-03 00:30:29.515946 | controller | skipping: Conditional result was False 2025-12-03 00:30:29.524977 | 2025-12-03 00:30:29.525079 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-03 00:30:29.560259 | 2025-12-03 00:30:29.560430 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-03 00:30:29.584673 | controller | skipping: Conditional result was False 2025-12-03 00:30:29.595823 | 2025-12-03 00:30:29.595953 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-03 00:30:29.610558 | controller | skipping: Conditional result was False 2025-12-03 00:30:29.617717 | 2025-12-03 00:30:29.617803 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-03 00:30:29.632815 | controller | skipping: Conditional result was False 2025-12-03 00:30:29.660603 | 2025-12-03 00:30:29.660721 | PLAY RECAP 2025-12-03 00:30:29.660768 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-03 00:30:29.660790 | 2025-12-03 00:30:29.754522 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-03 00:30:29.756392 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-03 00:30:30.389790 | 2025-12-03 00:30:30.389927 | PLAY [all:!appliance*] 2025-12-03 00:30:30.416740 | 2025-12-03 00:30:30.416842 | TASK [unregister the node] 2025-12-03 00:30:30.961743 | controller | skipping: Conditional result was False 2025-12-03 00:30:30.967960 | 2025-12-03 00:30:30.968034 | TASK [include_role : fetch-output] 2025-12-03 00:30:31.006764 | controller | ok 2025-12-03 00:30:31.046833 | 2025-12-03 00:30:31.046948 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-03 00:30:31.092327 | controller | skipping: Conditional result was False 2025-12-03 00:30:31.105415 | 2025-12-03 00:30:31.105562 | TASK [fetch-output : Set log path for single node] 2025-12-03 00:30:31.156277 | controller | ok 2025-12-03 00:30:31.168420 | 2025-12-03 00:30:31.168552 | LOOP [fetch-output : Ensure local output dirs] 2025-12-03 00:30:31.636528 | controller -> localhost | ok: "/var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/work/logs" 2025-12-03 00:30:31.896374 | controller -> localhost | changed: "/var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/work/artifacts" 2025-12-03 00:30:32.154602 | controller -> localhost | changed: "/var/lib/zuul/builds/fc05a287b3e74fb38d9c3d48f6b9404d/work/docs" 2025-12-03 00:30:32.166142 | 2025-12-03 00:30:32.166285 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-03 00:30:32.835541 | controller | changed: 2025-12-03 00:30:32.835978 | controller | .d..t...... ./ 2025-12-03 00:30:32.836045 | controller | cd+++++++++ controller/ 2025-12-03 00:30:32.836117 | controller | changed: All items complete 2025-12-03 00:30:32.836161 | 2025-12-03 00:30:33.301306 | controller | changed: .d..t...... ./ 2025-12-03 00:30:33.840299 | controller | changed: .d..t...... ./ 2025-12-03 00:30:33.865441 | 2025-12-03 00:30:33.865602 | TASK [include_role : fetch-output-openshift] 2025-12-03 00:30:33.889890 | controller | skipping: Conditional result was False 2025-12-03 00:30:33.896331 | 2025-12-03 00:30:33.896402 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-03 00:30:33.926897 | controller | skipping: Conditional result was False 2025-12-03 00:30:33.940440 | controller | skipping: Conditional result was False 2025-12-03 00:30:33.977096 | 2025-12-03 00:30:33.977236 | PLAY [localhost] 2025-12-03 00:30:33.989026 | 2025-12-03 00:30:33.989089 | TASK [Run Zuul manifest role] 2025-12-03 00:30:34.006979 | localhost | ok 2025-12-03 00:30:34.020784 | 2025-12-03 00:30:34.020847 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-03 00:30:34.460574 | localhost | changed 2025-12-03 00:30:34.472268 | 2025-12-03 00:30:34.472420 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-03 00:30:34.511098 | localhost | ok 2025-12-03 00:30:34.531502 | 2025-12-03 00:30:34.531642 | TASK [Set zuul-log-path fact] 2025-12-03 00:30:34.553474 | localhost | ok 2025-12-03 00:30:34.574581 | 2025-12-03 00:30:34.574697 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-03 00:30:34.606135 | localhost | ok 2025-12-03 00:30:34.617754 | 2025-12-03 00:30:34.617891 | LOOP [Run upload-logs-swift role] 2025-12-03 00:30:34.654965 | localhost | Output suppressed because no_log was given 2025-12-03 00:30:34.701836 | 2025-12-03 00:30:34.701969 | TASK [Set zuul-log-path fact] 2025-12-03 00:30:34.746752 | localhost | skipping: Conditional result was False 2025-12-03 00:30:34.754167 | 2025-12-03 00:30:34.754272 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-03 00:30:35.168128 | localhost -> localhost | ok: Runtime: 0:00:00.006160 2025-12-03 00:30:35.224568 | 2025-12-03 00:30:35.224728 | TASK [upload-logs-swift : Upload logs to swift]