2025-11-17 00:06:34.937350 | Job console starting... 2025-11-17 00:06:34.955193 | Updating repositories 2025-11-17 00:06:35.139775 | Preparing job workspace 2025-11-17 00:06:39.247195 | Running Ansible setup... 2025-11-17 00:06:44.024586 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-17 00:06:44.610874 | 2025-11-17 00:06:44.610987 | PLAY [localhost] 2025-11-17 00:06:44.619624 | 2025-11-17 00:06:44.619696 | TASK [Gathering Facts] 2025-11-17 00:06:45.590807 | localhost | ok 2025-11-17 00:06:45.611790 | 2025-11-17 00:06:45.611954 | TASK [Setup log path fact] 2025-11-17 00:06:45.632133 | localhost | ok 2025-11-17 00:06:45.649541 | 2025-11-17 00:06:45.649637 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-17 00:06:45.687554 | localhost | ok 2025-11-17 00:06:45.695350 | 2025-11-17 00:06:45.695415 | TASK [emit-job-header : Print job information] 2025-11-17 00:06:45.742701 | # Job Information 2025-11-17 00:06:45.742845 | Ansible Version: 2.15.12 2025-11-17 00:06:45.742876 | Job: ansible-test-sanity-docker-devel 2025-11-17 00:06:45.743065 | Pipeline: periodic 2025-11-17 00:06:45.743102 | Executor: ze01.softwarefactory-project.io 2025-11-17 00:06:45.743124 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-17 00:06:45.743145 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/efc/ansible/efcce6837b7a4aaabd95302c158c4612/ 2025-11-17 00:06:45.743165 | Event ID: 34106cb2d93c4462bd1cd6d67836b4e4 2025-11-17 00:06:45.746697 | 2025-11-17 00:06:45.746757 | LOOP [emit-job-header : Print node information] 2025-11-17 00:06:45.853833 | localhost | ok: 2025-11-17 00:06:45.854074 | localhost | # Node Information 2025-11-17 00:06:45.854124 | localhost | Inventory Hostname: controller 2025-11-17 00:06:45.854157 | localhost | Hostname: np0005524399 2025-11-17 00:06:45.854178 | localhost | Username: zuul 2025-11-17 00:06:45.854204 | localhost | Distro: Fedora 37 2025-11-17 00:06:45.854224 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-11-17 00:06:45.854241 | localhost | Region: ca-ymq-1 2025-11-17 00:06:45.854258 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-17 00:06:45.854275 | localhost | Product Name: OpenStack Nova 2025-11-17 00:06:45.854291 | localhost | Interface IP: 162.253.55.62 2025-11-17 00:06:45.870508 | 2025-11-17 00:06:45.870621 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-17 00:06:46.271148 | localhost -> localhost | changed 2025-11-17 00:06:46.277455 | 2025-11-17 00:06:46.277527 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-17 00:06:47.252602 | localhost -> localhost | changed 2025-11-17 00:06:47.290212 | 2025-11-17 00:06:47.290309 | PLAY [all:!appliance*] 2025-11-17 00:06:47.314934 | 2025-11-17 00:06:47.315072 | TASK [include_role : start-zuul-console] 2025-11-17 00:06:47.338345 | controller | ok 2025-11-17 00:06:47.358948 | 2025-11-17 00:06:47.359060 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-17 00:06:47.756833 | controller | ok 2025-11-17 00:06:47.772127 | 2025-11-17 00:06:47.772218 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-17 00:07:08.618006 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-17 00:07:08.632626 | 2025-11-17 00:07:08.632775 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-17 00:07:09.186516 | controller | skipping: Conditional result was False 2025-11-17 00:07:09.199621 | 2025-11-17 00:07:09.199760 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-17 00:07:09.226710 | controller | skipping: Conditional result was False 2025-11-17 00:07:09.239509 | 2025-11-17 00:07:09.239648 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-17 00:07:09.256825 | controller | skipping: Conditional result was False 2025-11-17 00:07:09.272367 | 2025-11-17 00:07:09.272505 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-17 00:07:09.299758 | controller | skipping: Conditional result was False 2025-11-17 00:07:09.316367 | 2025-11-17 00:07:09.316527 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-17 00:07:09.344663 | controller | skipping: Conditional result was False 2025-11-17 00:07:09.357832 | 2025-11-17 00:07:09.357971 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-17 00:07:09.374815 | controller | skipping: Conditional result was False 2025-11-17 00:07:09.398548 | 2025-11-17 00:07:09.398714 | TASK [Disable Fedora Modular] 2025-11-17 00:07:09.774620 | controller | changed 2025-11-17 00:07:09.787295 | 2025-11-17 00:07:09.787456 | TASK [Enable EPEL] 2025-11-17 00:07:09.825058 | controller | skipping: Conditional result was False 2025-11-17 00:07:09.839636 | 2025-11-17 00:07:09.839771 | TASK [Register the RHEL node] 2025-11-17 00:07:10.402918 | 2025-11-17 00:07:10.403216 | TASK [Show the subscription-manager status] 2025-11-17 00:07:10.960161 | controller | skipping: Conditional result was False 2025-11-17 00:07:10.974740 | 2025-11-17 00:07:10.974930 | TASK [Enable EPEL on RHEL] 2025-11-17 00:07:11.063882 | controller | skipping: Conditional result was False 2025-11-17 00:07:11.077741 | 2025-11-17 00:07:11.077956 | TASK [Install git and tox] 2025-11-17 00:08:07.100488 | controller | changed 2025-11-17 00:08:07.114093 | 2025-11-17 00:08:07.114237 | TASK [include_role : prepare-workspace] 2025-11-17 00:08:07.159720 | controller | ok 2025-11-17 00:08:07.193801 | 2025-11-17 00:08:07.193947 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-17 00:08:07.431776 | controller | ok 2025-11-17 00:08:07.446268 | 2025-11-17 00:08:07.446390 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-17 00:08:19.442126 | controller | Output suppressed because no_log was given 2025-11-17 00:08:19.456787 | 2025-11-17 00:08:19.456898 | TASK [include_role : prepare-workspace-openshift] 2025-11-17 00:08:19.482912 | controller | skipping: Conditional result was False 2025-11-17 00:08:19.505405 | 2025-11-17 00:08:19.505484 | PLAY [all:!appliance] 2025-11-17 00:08:19.521581 | 2025-11-17 00:08:19.521645 | TASK [Run add-build-sshkey role (RSA)] 2025-11-17 00:08:19.552896 | controller | ok 2025-11-17 00:08:19.570107 | 2025-11-17 00:08:19.570217 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-17 00:08:19.839200 | controller -> localhost | ok 2025-11-17 00:08:19.845957 | 2025-11-17 00:08:19.846053 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-17 00:08:19.878162 | controller | ok 2025-11-17 00:08:19.894345 | controller | included: /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-17 00:08:19.901496 | 2025-11-17 00:08:19.901561 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-17 00:08:20.311450 | controller -> localhost | Generating public/private rsa key pair. 2025-11-17 00:08:20.311721 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/work/efcce6837b7a4aaabd95302c158c4612_id_rsa. 2025-11-17 00:08:20.311781 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/work/efcce6837b7a4aaabd95302c158c4612_id_rsa.pub. 2025-11-17 00:08:20.311812 | controller -> localhost | The key fingerprint is: 2025-11-17 00:08:20.311840 | controller -> localhost | SHA256:oDabUtlnhVyR9rrD46g6xLzuSbK55YdytAMd13aDgMo zuul-build-sshkey 2025-11-17 00:08:20.311864 | controller -> localhost | The key's randomart image is: 2025-11-17 00:08:20.311891 | controller -> localhost | +---[RSA 2048]----+ 2025-11-17 00:08:20.311916 | controller -> localhost | | . oo | 2025-11-17 00:08:20.311942 | controller -> localhost | | . .. oo | 2025-11-17 00:08:20.311967 | controller -> localhost | | . . .ooo.. | 2025-11-17 00:08:20.311994 | controller -> localhost | | E .+..+.o . | 2025-11-17 00:08:20.312092 | controller -> localhost | | +*o..S. o | 2025-11-17 00:08:20.312134 | controller -> localhost | | .o*+ o . | 2025-11-17 00:08:20.312165 | controller -> localhost | | o+=+ . . | 2025-11-17 00:08:20.312192 | controller -> localhost | | .OB.. .= | 2025-11-17 00:08:20.312217 | controller -> localhost | | +**=.....o | 2025-11-17 00:08:20.312246 | controller -> localhost | +----[SHA256]-----+ 2025-11-17 00:08:20.312312 | controller -> localhost | ok: Runtime: 0:00:00.037166 2025-11-17 00:08:20.320268 | 2025-11-17 00:08:20.320334 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-17 00:08:20.342604 | controller | ok 2025-11-17 00:08:20.356408 | controller | included: /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-17 00:08:20.365679 | 2025-11-17 00:08:20.365772 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-17 00:08:20.379413 | controller | skipping: Conditional result was False 2025-11-17 00:08:20.386836 | 2025-11-17 00:08:20.386935 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-17 00:08:20.796899 | controller | changed 2025-11-17 00:08:20.802680 | 2025-11-17 00:08:20.802744 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-17 00:08:21.015967 | controller | ok 2025-11-17 00:08:21.022122 | 2025-11-17 00:08:21.022184 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-17 00:08:21.626469 | controller | changed 2025-11-17 00:08:21.639727 | 2025-11-17 00:08:21.639908 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-17 00:08:22.277968 | controller | changed 2025-11-17 00:08:22.284303 | 2025-11-17 00:08:22.284397 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-17 00:08:22.309280 | controller | skipping: Conditional result was False 2025-11-17 00:08:22.316504 | 2025-11-17 00:08:22.316593 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-17 00:08:22.689211 | controller -> localhost | changed 2025-11-17 00:08:22.744076 | 2025-11-17 00:08:22.744189 | TASK [add-build-sshkey : Add back temp key] 2025-11-17 00:08:23.022205 | controller -> localhost | Identity added: /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/work/efcce6837b7a4aaabd95302c158c4612_id_rsa (zuul-build-sshkey) 2025-11-17 00:08:23.022392 | controller -> localhost | ok: Runtime: 0:00:00.012877 2025-11-17 00:08:23.028908 | 2025-11-17 00:08:23.028972 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-17 00:08:23.366349 | controller | ok 2025-11-17 00:08:23.373660 | 2025-11-17 00:08:23.373797 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-17 00:08:23.398171 | controller | skipping: Conditional result was False 2025-11-17 00:08:23.411200 | 2025-11-17 00:08:23.411298 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-17 00:08:23.432143 | controller | ok 2025-11-17 00:08:23.452918 | 2025-11-17 00:08:23.453046 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-17 00:08:23.679716 | controller -> localhost | ok 2025-11-17 00:08:23.687773 | 2025-11-17 00:08:23.687863 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-17 00:08:23.720416 | controller | ok 2025-11-17 00:08:23.737225 | controller | included: /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-17 00:08:23.743900 | 2025-11-17 00:08:23.744155 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-17 00:08:24.012283 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-17 00:08:24.012453 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/work/efcce6837b7a4aaabd95302c158c4612_id_ecdsa. 2025-11-17 00:08:24.012482 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/work/efcce6837b7a4aaabd95302c158c4612_id_ecdsa.pub. 2025-11-17 00:08:24.012519 | controller -> localhost | The key fingerprint is: 2025-11-17 00:08:24.012540 | controller -> localhost | SHA256:XlOMFYurw7E2oqK5MLV+EZGVEW08ogdrpPkMiBK+aXo zuul-build-sshkey 2025-11-17 00:08:24.012559 | controller -> localhost | The key's randomart image is: 2025-11-17 00:08:24.012578 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-17 00:08:24.012596 | controller -> localhost | | o+* o. | 2025-11-17 00:08:24.012614 | controller -> localhost | |. = o = = . | 2025-11-17 00:08:24.012632 | controller -> localhost | |oo + = o .o + | 2025-11-17 00:08:24.012649 | controller -> localhost | |+.+ = . o | 2025-11-17 00:08:24.012667 | controller -> localhost | |. += o S + | 2025-11-17 00:08:24.012684 | controller -> localhost | | = .+ o = . | 2025-11-17 00:08:24.012701 | controller -> localhost | |= . .. O | 2025-11-17 00:08:24.012718 | controller -> localhost | |o+E .. o o | 2025-11-17 00:08:24.012735 | controller -> localhost | |++.o. | 2025-11-17 00:08:24.012752 | controller -> localhost | +----[SHA256]-----+ 2025-11-17 00:08:24.012798 | controller -> localhost | ok: Runtime: 0:00:00.007926 2025-11-17 00:08:24.019750 | 2025-11-17 00:08:24.019819 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-17 00:08:24.050522 | controller | ok 2025-11-17 00:08:24.058368 | controller | included: /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-17 00:08:24.067635 | 2025-11-17 00:08:24.067719 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-17 00:08:24.082047 | controller | skipping: Conditional result was False 2025-11-17 00:08:24.089733 | 2025-11-17 00:08:24.089835 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-17 00:08:24.346621 | controller | changed 2025-11-17 00:08:24.352766 | 2025-11-17 00:08:24.352843 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-17 00:08:24.569696 | controller | ok 2025-11-17 00:08:24.581833 | 2025-11-17 00:08:24.581954 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-17 00:08:25.190580 | controller | changed 2025-11-17 00:08:25.199731 | 2025-11-17 00:08:25.199828 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-17 00:08:25.751084 | controller | changed 2025-11-17 00:08:25.757172 | 2025-11-17 00:08:25.757236 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-17 00:08:25.781163 | controller | skipping: Conditional result was False 2025-11-17 00:08:25.790720 | 2025-11-17 00:08:25.790813 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-17 00:08:26.039357 | controller -> localhost | changed 2025-11-17 00:08:26.057036 | 2025-11-17 00:08:26.057177 | TASK [add-build-sshkey : Add back temp key] 2025-11-17 00:08:26.347865 | controller -> localhost | Identity added: /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/work/efcce6837b7a4aaabd95302c158c4612_id_ecdsa (zuul-build-sshkey) 2025-11-17 00:08:26.348067 | controller -> localhost | ok: Runtime: 0:00:00.008528 2025-11-17 00:08:26.356381 | 2025-11-17 00:08:26.356455 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-17 00:08:26.560332 | controller | ok 2025-11-17 00:08:26.566253 | 2025-11-17 00:08:26.566346 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-17 00:08:26.587245 | controller | skipping: Conditional result was False 2025-11-17 00:08:26.598816 | 2025-11-17 00:08:26.598907 | TASK [include_role : remove-zuul-sshkey] 2025-11-17 00:08:26.622880 | controller | skipping: Conditional result was False 2025-11-17 00:08:26.629669 | 2025-11-17 00:08:26.629734 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-17 00:08:26.858872 | controller | ok: "logs" 2025-11-17 00:08:26.859389 | controller | ok: All items complete 2025-11-17 00:08:26.859453 | 2025-11-17 00:08:27.041000 | controller | ok: "artifacts" 2025-11-17 00:08:27.237494 | controller | ok: "docs" 2025-11-17 00:08:27.254871 | 2025-11-17 00:08:27.254965 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-17 00:08:27.523330 | controller | changed: "logs" 2025-11-17 00:08:27.727901 | controller | changed: "artifacts" 2025-11-17 00:08:27.928833 | controller | changed: "docs" 2025-11-17 00:08:27.985051 | 2025-11-17 00:08:27.985188 | PLAY RECAP 2025-11-17 00:08:27.985249 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-17 00:08:27.985286 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-17 00:08:27.985311 | 2025-11-17 00:08:28.118871 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-17 00:08:28.120625 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-17 00:08:28.731286 | 2025-11-17 00:08:28.731407 | PLAY [all] 2025-11-17 00:08:28.754085 | 2025-11-17 00:08:28.754197 | TASK [Install binary dependencies] 2025-11-17 00:08:28.804326 | controller | ok 2025-11-17 00:08:28.825473 | 2025-11-17 00:08:28.825585 | TASK [bindep : Include find tasks] 2025-11-17 00:08:28.864813 | controller | ok 2025-11-17 00:08:28.873262 | controller | included: /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-17 00:08:28.879729 | 2025-11-17 00:08:28.879792 | TASK [bindep : Look for bindep.txt] 2025-11-17 00:08:29.253200 | controller | ok 2025-11-17 00:08:29.265265 | 2025-11-17 00:08:29.265433 | TASK [bindep : Define bindep_file fact] 2025-11-17 00:08:29.291197 | controller | skipping: Conditional result was False 2025-11-17 00:08:29.311522 | 2025-11-17 00:08:29.311741 | TASK [bindep : Look for other-requirements.txt] 2025-11-17 00:08:29.529484 | controller | ok 2025-11-17 00:08:29.537962 | 2025-11-17 00:08:29.538109 | TASK [bindep : Define bindep_file fact] 2025-11-17 00:08:29.563277 | controller | skipping: Conditional result was False 2025-11-17 00:08:29.576220 | 2025-11-17 00:08:29.576395 | TASK [bindep : Look for bindep fallback file] 2025-11-17 00:08:29.613509 | controller | skipping: Conditional result was False 2025-11-17 00:08:29.623350 | 2025-11-17 00:08:29.623484 | TASK [bindep : Define bindep_file fact] 2025-11-17 00:08:29.669035 | controller | skipping: Conditional result was False 2025-11-17 00:08:29.677796 | 2025-11-17 00:08:29.677889 | TASK [bindep : Include bindep tasks] 2025-11-17 00:08:29.702057 | controller | skipping: Conditional result was False 2025-11-17 00:08:29.710341 | 2025-11-17 00:08:29.710429 | TASK [bindep : Include install tasks] 2025-11-17 00:08:29.735394 | controller | skipping: Conditional result was False 2025-11-17 00:08:29.744062 | 2025-11-17 00:08:29.744165 | LOOP [bindep : Include package tasks] 2025-11-17 00:08:29.814145 | 2025-11-17 00:08:29.814354 | TASK [Run test-setup role] 2025-11-17 00:08:29.839531 | controller | ok 2025-11-17 00:08:29.859478 | 2025-11-17 00:08:29.859549 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-17 00:08:30.069149 | controller | ok 2025-11-17 00:08:30.083213 | 2025-11-17 00:08:30.083356 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-17 00:08:30.633173 | controller | skipping: Conditional result was False 2025-11-17 00:08:30.689084 | 2025-11-17 00:08:30.689204 | PLAY RECAP 2025-11-17 00:08:30.689259 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-17 00:08:30.689287 | 2025-11-17 00:08:30.807117 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-17 00:08:30.808773 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-17 00:08:31.449574 | 2025-11-17 00:08:31.449766 | PLAY [controller] 2025-11-17 00:08:31.470349 | 2025-11-17 00:08:31.470494 | TASK [Create the /root directory] 2025-11-17 00:08:31.842324 | controller | ok 2025-11-17 00:08:31.848582 | 2025-11-17 00:08:31.848652 | TASK [Install glibc-langpack-en] 2025-11-17 00:08:35.886205 | controller | ok: Nothing to do 2025-11-17 00:08:35.893861 | 2025-11-17 00:08:35.893943 | TASK [Ensure controller directory exists] 2025-11-17 00:08:36.119724 | controller | changed 2025-11-17 00:08:36.134345 | 2025-11-17 00:08:36.134486 | TASK [Install container runtime] 2025-11-17 00:08:36.211297 | controller | ok 2025-11-17 00:08:36.269284 | 2025-11-17 00:08:36.269421 | LOOP [ensure-podman : Find distribution installation] 2025-11-17 00:08:36.310437 | controller | ok: "/var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-17 00:08:36.332274 | controller | included: /var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-17 00:08:36.343897 | 2025-11-17 00:08:36.344033 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-17 00:09:41.284568 | controller | changed 2025-11-17 00:09:41.298628 | 2025-11-17 00:09:41.298791 | TASK [ensure-podman : Fetch podman version] 2025-11-17 00:09:41.855710 | controller | Client: Podman Engine 2025-11-17 00:09:41.883333 | controller | Version: 4.6.2 2025-11-17 00:09:41.883372 | controller | API Version: 4.6.2 2025-11-17 00:09:41.883378 | controller | Go Version: go1.19.12 2025-11-17 00:09:41.883401 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-17 00:09:41.883410 | controller | OS/Arch: linux/amd64 2025-11-17 00:09:42.352998 | controller | ok: Runtime: 0:00:00.199678 2025-11-17 00:09:42.367483 | 2025-11-17 00:09:42.367657 | TASK [ensure-podman : Print podman version installed] 2025-11-17 00:09:42.430330 | Podman version: Client: Podman Engine 2025-11-17 00:09:42.430635 | Version: 4.6.2 2025-11-17 00:09:42.430702 | API Version: 4.6.2 2025-11-17 00:09:42.430751 | Go Version: go1.19.12 2025-11-17 00:09:42.430796 | Built: Mon Aug 28 19:38:31 2023 2025-11-17 00:09:42.430845 | OS/Arch: linux/amd64 2025-11-17 00:09:42.449209 | 2025-11-17 00:09:42.449395 | TASK [ensure-podman : Validate podman engine] 2025-11-17 00:09:43.006337 | controller | skipping: Conditional result was False 2025-11-17 00:09:43.023831 | 2025-11-17 00:09:43.024077 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-17 00:09:43.053153 | controller | skipping: Conditional result was False 2025-11-17 00:09:43.081469 | 2025-11-17 00:09:43.081643 | TASK [Ensure python3.8 is present] 2025-11-17 00:09:43.108212 | controller | skipping: Conditional result was False 2025-11-17 00:09:43.117119 | 2025-11-17 00:09:43.117248 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-17 00:09:43.142422 | controller | ok 2025-11-17 00:09:43.173291 | 2025-11-17 00:09:43.173408 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-17 00:09:45.013816 | controller | ok: Nothing to do 2025-11-17 00:09:45.027328 | 2025-11-17 00:09:45.027483 | TASK [our-ensure-python : Also install python3-devel] 2025-11-17 00:09:54.210588 | controller | changed 2025-11-17 00:09:54.235846 | 2025-11-17 00:09:54.236060 | TASK [Run ensure-virtualenv role] 2025-11-17 00:09:54.261675 | controller | ok 2025-11-17 00:09:54.289355 | 2025-11-17 00:09:54.289457 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-17 00:09:54.543032 | controller | /usr/bin/virtualenv 2025-11-17 00:09:54.850626 | controller | ok: Runtime: 0:00:00.006235 2025-11-17 00:09:54.863448 | 2025-11-17 00:09:54.863591 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-17 00:09:54.898812 | controller | skipping: Conditional result was False 2025-11-17 00:09:54.899281 | controller | ok: All items complete 2025-11-17 00:09:54.899341 | 2025-11-17 00:09:54.925915 | 2025-11-17 00:09:54.926170 | TASK [Find the full path of the Python interpreter] 2025-11-17 00:09:55.146653 | controller | /usr/bin/python3 2025-11-17 00:09:55.471965 | controller | ok 2025-11-17 00:09:55.485799 | 2025-11-17 00:09:55.485973 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-17 00:09:56.414839 | controller | created virtual environment CPython3.11.0.final.0-64 in 503ms 2025-11-17 00:09:56.431351 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-17 00:09:56.431386 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul/.local/share/virtualenv) 2025-11-17 00:09:56.431395 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-17 00:09:56.431408 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-17 00:09:56.542847 | controller | changed 2025-11-17 00:09:56.551751 | 2025-11-17 00:09:56.551842 | TASK [Set selinux package] 2025-11-17 00:09:56.589485 | controller | ok 2025-11-17 00:09:56.601685 | 2025-11-17 00:09:56.601829 | TASK [Set selinux package (Fedora)] 2025-11-17 00:09:56.662387 | controller | ok 2025-11-17 00:09:56.674116 | 2025-11-17 00:09:56.674259 | TASK [Install selinux into virtualenv] 2025-11-17 00:10:10.177595 | controller | Collecting selinux-please-lie-to-me 2025-11-17 00:10:22.440275 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-17 00:10:22.747596 | controller | Collecting setuptools<50.0.0 2025-11-17 00:10:22.768733 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-17 00:10:22.809268 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.2 MB/s eta 0:00:00 2025-11-17 00:10:22.891162 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-17 00:10:22.891386 | controller | Attempting uninstall: setuptools 2025-11-17 00:10:22.893772 | controller | Found existing installation: setuptools 62.6.0 2025-11-17 00:10:22.952544 | controller | Uninstalling setuptools-62.6.0: 2025-11-17 00:10:22.960200 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-17 00:10:23.303565 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-17 00:10:34.803284 | controller | 2025-11-17 00:10:34.884892 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-17 00:10:34.884934 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-17 00:10:35.258812 | controller | ok: Runtime: 0:00:37.985216 2025-11-17 00:10:35.272518 | 2025-11-17 00:10:35.272661 | TASK [Install pytest-forked into virtualenv] 2025-11-17 00:10:47.066621 | controller | Collecting pytest-forked 2025-11-17 00:10:59.289057 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-17 00:10:59.342430 | controller | Collecting py 2025-11-17 00:10:59.348280 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-17 00:10:59.367357 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 6.4 MB/s eta 0:00:00 2025-11-17 00:10:59.483389 | controller | Collecting pytest>=3.10 2025-11-17 00:10:59.659502 | controller | Downloading pytest-9.0.1-py3-none-any.whl (373 kB) 2025-11-17 00:10:59.675933 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.7/373.7 kB 28.8 MB/s eta 0:00:00 2025-11-17 00:10:59.738405 | controller | Collecting iniconfig>=1.0.1 2025-11-17 00:10:59.746532 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-17 00:10:59.825647 | controller | Collecting packaging>=22 2025-11-17 00:10:59.828782 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-17 00:10:59.836334 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 10.7 MB/s eta 0:00:00 2025-11-17 00:10:59.907110 | controller | Collecting pluggy<2,>=1.5 2025-11-17 00:10:59.912092 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-17 00:10:59.985832 | controller | Collecting pygments>=2.7.2 2025-11-17 00:10:59.999950 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-17 00:11:00.046793 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 28.6 MB/s eta 0:00:00 2025-11-17 00:11:00.117582 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-17 00:11:01.194525 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.1 pytest-forked-1.6.0 2025-11-17 00:11:01.203141 | controller | 2025-11-17 00:11:01.272284 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-17 00:11:01.272337 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-17 00:11:01.343607 | controller | ok: Runtime: 0:00:25.765648 2025-11-17 00:11:01.350566 | 2025-11-17 00:11:01.350646 | TASK [Update pip] 2025-11-17 00:11:01.859878 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-17 00:11:14.353046 | controller | Collecting pip 2025-11-17 00:11:26.490106 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-17 00:11:26.596599 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 17.5 MB/s eta 0:00:00 2025-11-17 00:11:26.664536 | controller | Installing collected packages: pip 2025-11-17 00:11:26.664718 | controller | Attempting uninstall: pip 2025-11-17 00:11:26.666953 | controller | Found existing installation: pip 22.2.2 2025-11-17 00:11:26.805692 | controller | Uninstalling pip-22.2.2: 2025-11-17 00:11:26.820538 | controller | Successfully uninstalled pip-22.2.2 2025-11-17 00:11:27.670090 | controller | Successfully installed pip-25.3 2025-11-17 00:11:27.903937 | controller | ok: Runtime: 0:00:26.200419 2025-11-17 00:11:27.956305 | 2025-11-17 00:11:27.956591 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-17 00:11:28.230888 | controller | changed 2025-11-17 00:11:28.246750 | 2025-11-17 00:11:28.246901 | TASK [Install ansible into virtualenv] 2025-11-17 00:11:28.774340 | controller | Processing ./src/github.com/ansible/ansible 2025-11-17 00:11:28.777580 | controller | Installing build dependencies: started 2025-11-17 00:11:51.454507 | controller | Installing build dependencies: finished with status 'done' 2025-11-17 00:11:51.456427 | controller | Getting requirements to build wheel: started 2025-11-17 00:11:52.224202 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-17 00:11:52.225912 | controller | Preparing metadata (pyproject.toml): started 2025-11-17 00:11:52.706473 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-17 00:11:52.711838 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while. 2025-11-17 00:11:52.716832 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-17 00:11:52.820186 | controller | ERROR 2025-11-17 00:11:52.820417 | controller | { 2025-11-17 00:11:52.820479 | controller | "delta": "0:00:24.279365", 2025-11-17 00:11:52.820526 | controller | "end": "2025-11-17 00:11:52.777177", 2025-11-17 00:11:52.820564 | controller | "msg": "non-zero return code", 2025-11-17 00:11:52.820617 | controller | "rc": 1, 2025-11-17 00:11:52.820654 | controller | "start": "2025-11-17 00:11:28.497812" 2025-11-17 00:11:52.820689 | controller | } failure 2025-11-17 00:11:52.823066 | 2025-11-17 00:11:52.823164 | PLAY RECAP 2025-11-17 00:11:52.823245 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-17 00:11:52.823289 | 2025-11-17 00:11:52.938259 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-17 00:11:52.940389 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-17 00:11:53.586892 | 2025-11-17 00:11:53.587001 | PLAY [all] 2025-11-17 00:11:53.607792 | 2025-11-17 00:11:53.607870 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-17 00:11:53.984455 | controller | changed: non-zero return code 2025-11-17 00:11:53.998494 | 2025-11-17 00:11:53.998799 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-17 00:11:54.029820 | controller | skipping: Conditional result was False 2025-11-17 00:11:54.045075 | 2025-11-17 00:11:54.045309 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-17 00:11:54.091308 | 2025-11-17 00:11:54.091696 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-17 00:11:54.134629 | 2025-11-17 00:11:54.135659 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-17 00:11:54.162848 | controller | skipping: Conditional result was False 2025-11-17 00:11:54.182819 | 2025-11-17 00:11:54.183003 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-17 00:11:54.217295 | 2025-11-17 00:11:54.217465 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-17 00:11:54.242393 | controller | skipping: Conditional result was False 2025-11-17 00:11:54.250519 | 2025-11-17 00:11:54.250606 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-17 00:11:54.275282 | controller | skipping: Conditional result was False 2025-11-17 00:11:54.283604 | 2025-11-17 00:11:54.283686 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-17 00:11:54.308239 | controller | skipping: Conditional result was False 2025-11-17 00:11:54.344530 | 2025-11-17 00:11:54.344618 | PLAY RECAP 2025-11-17 00:11:54.344673 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-17 00:11:54.344700 | 2025-11-17 00:11:54.456921 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-17 00:11:54.458846 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-17 00:11:55.153532 | 2025-11-17 00:11:55.153684 | PLAY [all:!appliance*] 2025-11-17 00:11:55.178709 | 2025-11-17 00:11:55.178837 | TASK [unregister the node] 2025-11-17 00:11:55.710362 | controller | skipping: Conditional result was False 2025-11-17 00:11:55.724762 | 2025-11-17 00:11:55.724933 | TASK [include_role : fetch-output] 2025-11-17 00:11:55.774789 | controller | ok 2025-11-17 00:11:55.808632 | 2025-11-17 00:11:55.808739 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-17 00:11:55.884642 | controller | skipping: Conditional result was False 2025-11-17 00:11:55.893191 | 2025-11-17 00:11:55.893398 | TASK [fetch-output : Set log path for single node] 2025-11-17 00:11:55.936313 | controller | ok 2025-11-17 00:11:55.944181 | 2025-11-17 00:11:55.944271 | LOOP [fetch-output : Ensure local output dirs] 2025-11-17 00:11:56.419491 | controller -> localhost | ok: "/var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/work/logs" 2025-11-17 00:11:56.647861 | controller -> localhost | changed: "/var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/work/artifacts" 2025-11-17 00:11:56.866571 | controller -> localhost | changed: "/var/lib/zuul/builds/efcce6837b7a4aaabd95302c158c4612/work/docs" 2025-11-17 00:11:56.889949 | 2025-11-17 00:11:56.890146 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-17 00:11:57.558926 | controller | changed: 2025-11-17 00:11:57.559811 | controller | .d..t...... ./ 2025-11-17 00:11:57.559890 | controller | cd+++++++++ controller/ 2025-11-17 00:11:57.559959 | controller | changed: All items complete 2025-11-17 00:11:57.560003 | 2025-11-17 00:11:58.074290 | controller | changed: .d..t...... ./ 2025-11-17 00:11:58.629374 | controller | changed: .d..t...... ./ 2025-11-17 00:11:58.663970 | 2025-11-17 00:11:58.664229 | TASK [include_role : fetch-output-openshift] 2025-11-17 00:11:58.691960 | controller | skipping: Conditional result was False 2025-11-17 00:11:58.710732 | 2025-11-17 00:11:58.710881 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-17 00:11:58.748499 | controller | skipping: Conditional result was False 2025-11-17 00:11:58.763577 | controller | skipping: Conditional result was False 2025-11-17 00:11:58.811513 | 2025-11-17 00:11:58.811650 | PLAY [localhost] 2025-11-17 00:11:58.828340 | 2025-11-17 00:11:58.828426 | TASK [Run Zuul manifest role] 2025-11-17 00:11:58.847538 | localhost | ok 2025-11-17 00:11:58.861685 | 2025-11-17 00:11:58.861768 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-17 00:11:59.314633 | localhost | changed 2025-11-17 00:11:59.327615 | 2025-11-17 00:11:59.327808 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-17 00:11:59.382908 | localhost | ok 2025-11-17 00:11:59.393811 | 2025-11-17 00:11:59.393960 | TASK [Set zuul-log-path fact] 2025-11-17 00:11:59.421220 | localhost | ok 2025-11-17 00:11:59.438550 | 2025-11-17 00:11:59.438697 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-17 00:11:59.472559 | localhost | ok 2025-11-17 00:11:59.483243 | 2025-11-17 00:11:59.483340 | LOOP [Run upload-logs-swift role] 2025-11-17 00:11:59.516570 | localhost | Output suppressed because no_log was given 2025-11-17 00:11:59.545477 | 2025-11-17 00:11:59.545728 | TASK [Set zuul-log-path fact] 2025-11-17 00:11:59.581650 | localhost | skipping: Conditional result was False 2025-11-17 00:11:59.589427 | 2025-11-17 00:11:59.589641 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-17 00:12:00.018045 | localhost -> localhost | ok: Runtime: 0:00:00.008411 2025-11-17 00:12:00.063382 | 2025-11-17 00:12:00.063529 | TASK [upload-logs-swift : Upload logs to swift]