2025-11-09 00:13:36.356115 | Job console starting... 2025-11-09 00:13:36.378417 | Updating repositories 2025-11-09 00:13:36.694186 | Preparing job workspace 2025-11-09 00:13:41.023149 | Running Ansible setup... 2025-11-09 00:13:49.544029 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-09 00:13:50.137580 | 2025-11-09 00:13:50.137735 | PLAY [localhost] 2025-11-09 00:13:50.157329 | 2025-11-09 00:13:50.157405 | TASK [Gathering Facts] 2025-11-09 00:13:51.158080 | localhost | ok 2025-11-09 00:13:51.194956 | 2025-11-09 00:13:51.195178 | TASK [Setup log path fact] 2025-11-09 00:13:51.219402 | localhost | ok 2025-11-09 00:13:51.240400 | 2025-11-09 00:13:51.240570 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-09 00:13:51.275152 | localhost | ok 2025-11-09 00:13:51.286506 | 2025-11-09 00:13:51.286662 | TASK [emit-job-header : Print job information] 2025-11-09 00:13:51.323363 | # Job Information 2025-11-09 00:13:51.323576 | Ansible Version: 2.15.12 2025-11-09 00:13:51.323610 | Job: ansible-test-sanity-docker-devel 2025-11-09 00:13:51.323631 | Pipeline: periodic 2025-11-09 00:13:51.323661 | Executor: ze04.softwarefactory-project.io 2025-11-09 00:13:51.323707 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-09 00:13:51.323746 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/23f/ansible/23f7d198db3e4de2a2f3de1179514ed9/ 2025-11-09 00:13:51.323777 | Event ID: 280be395c61a4a10afa9abd9d444e89a 2025-11-09 00:13:51.329381 | 2025-11-09 00:13:51.329610 | LOOP [emit-job-header : Print node information] 2025-11-09 00:13:51.445133 | localhost | ok: 2025-11-09 00:13:51.445350 | localhost | # Node Information 2025-11-09 00:13:51.445383 | localhost | Inventory Hostname: controller 2025-11-09 00:13:51.445411 | localhost | Hostname: np0005515821 2025-11-09 00:13:51.445437 | localhost | Username: zuul 2025-11-09 00:13:51.446435 | localhost | Distro: Fedora 37 2025-11-09 00:13:51.446481 | localhost | Provider: ansible-vexxhost-ams1 2025-11-09 00:13:51.446518 | localhost | Region: ams1 2025-11-09 00:13:51.446542 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-09 00:13:51.446566 | localhost | Product Name: OpenStack Nova 2025-11-09 00:13:51.446589 | localhost | Interface IP: 38.129.16.97 2025-11-09 00:13:51.471275 | 2025-11-09 00:13:51.471506 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-09 00:13:52.002595 | localhost -> localhost | changed 2025-11-09 00:13:52.010370 | 2025-11-09 00:13:52.010501 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-09 00:13:53.059853 | localhost -> localhost | changed 2025-11-09 00:13:53.080371 | 2025-11-09 00:13:53.080437 | PLAY [all:!appliance*] 2025-11-09 00:13:53.098254 | 2025-11-09 00:13:53.098354 | TASK [include_role : start-zuul-console] 2025-11-09 00:13:53.119419 | controller | ok 2025-11-09 00:13:53.133264 | 2025-11-09 00:13:53.133348 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-09 00:13:54.179140 | controller | ok 2025-11-09 00:13:54.191612 | 2025-11-09 00:13:54.191743 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-09 00:13:56.613166 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-09 00:13:56.620625 | 2025-11-09 00:13:56.620709 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-09 00:13:56.982646 | controller | skipping: Conditional result was False 2025-11-09 00:13:56.989411 | 2025-11-09 00:13:56.989480 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-09 00:13:57.014910 | controller | skipping: Conditional result was False 2025-11-09 00:13:57.026219 | 2025-11-09 00:13:57.026330 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-09 00:13:57.057858 | controller | skipping: Conditional result was False 2025-11-09 00:13:57.066587 | 2025-11-09 00:13:57.066719 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-09 00:13:57.094214 | controller | skipping: Conditional result was False 2025-11-09 00:13:57.102802 | 2025-11-09 00:13:57.102928 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-09 00:13:57.130898 | controller | skipping: Conditional result was False 2025-11-09 00:13:57.140073 | 2025-11-09 00:13:57.140168 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-09 00:13:57.166256 | controller | skipping: Conditional result was False 2025-11-09 00:13:57.180253 | 2025-11-09 00:13:57.180364 | TASK [Disable Fedora Modular] 2025-11-09 00:13:58.230273 | controller | changed 2025-11-09 00:13:58.236365 | 2025-11-09 00:13:58.236465 | TASK [Enable EPEL] 2025-11-09 00:13:58.262631 | controller | skipping: Conditional result was False 2025-11-09 00:13:58.271964 | 2025-11-09 00:13:58.272159 | TASK [Register the RHEL node] 2025-11-09 00:13:58.690659 | 2025-11-09 00:13:58.690892 | TASK [Show the subscription-manager status] 2025-11-09 00:13:59.061236 | controller | skipping: Conditional result was False 2025-11-09 00:13:59.070194 | 2025-11-09 00:13:59.070285 | TASK [Enable EPEL on RHEL] 2025-11-09 00:13:59.484454 | controller | skipping: Conditional result was False 2025-11-09 00:13:59.498447 | 2025-11-09 00:13:59.498628 | TASK [Install git and tox] 2025-11-09 00:16:22.911077 | controller | changed 2025-11-09 00:16:22.917570 | 2025-11-09 00:16:22.917637 | TASK [include_role : prepare-workspace] 2025-11-09 00:16:22.951545 | controller | ok 2025-11-09 00:16:22.975456 | 2025-11-09 00:16:22.975559 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-09 00:16:23.825403 | controller | ok 2025-11-09 00:16:23.840331 | 2025-11-09 00:16:23.840483 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-09 00:16:39.927548 | controller | Output suppressed because no_log was given 2025-11-09 00:16:39.937595 | 2025-11-09 00:16:39.937664 | TASK [include_role : prepare-workspace-openshift] 2025-11-09 00:16:39.963763 | controller | skipping: Conditional result was False 2025-11-09 00:16:39.987274 | 2025-11-09 00:16:39.987377 | PLAY [all:!appliance] 2025-11-09 00:16:40.003585 | 2025-11-09 00:16:40.003663 | TASK [Run add-build-sshkey role (RSA)] 2025-11-09 00:16:40.035637 | controller | ok 2025-11-09 00:16:40.050730 | 2025-11-09 00:16:40.050805 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-09 00:16:40.301275 | controller -> localhost | ok 2025-11-09 00:16:40.313107 | 2025-11-09 00:16:40.313240 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-09 00:16:40.349594 | controller | ok 2025-11-09 00:16:40.373367 | controller | included: /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-09 00:16:40.383191 | 2025-11-09 00:16:40.383288 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-09 00:16:40.878284 | controller -> localhost | Generating public/private rsa key pair. 2025-11-09 00:16:40.878559 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/work/23f7d198db3e4de2a2f3de1179514ed9_id_rsa. 2025-11-09 00:16:40.878602 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/work/23f7d198db3e4de2a2f3de1179514ed9_id_rsa.pub. 2025-11-09 00:16:40.878632 | controller -> localhost | The key fingerprint is: 2025-11-09 00:16:40.878661 | controller -> localhost | SHA256:gqjLAAS4U3sGjy+GqqO7KFNPtMX1bZB5OYgGwVpr7l0 zuul-build-sshkey 2025-11-09 00:16:40.878725 | controller -> localhost | The key's randomart image is: 2025-11-09 00:16:40.878756 | controller -> localhost | +---[RSA 2048]----+ 2025-11-09 00:16:40.878784 | controller -> localhost | |o .oo . + . | 2025-11-09 00:16:40.878813 | controller -> localhost | |o o o + = + | 2025-11-09 00:16:40.878840 | controller -> localhost | | + = + + . + . | 2025-11-09 00:16:40.878866 | controller -> localhost | |+ o.*.= . o | 2025-11-09 00:16:40.878893 | controller -> localhost | |.o.=.=. S . | 2025-11-09 00:16:40.878932 | controller -> localhost | |o.+ + .. E | 2025-11-09 00:16:40.878965 | controller -> localhost | |+o + . . . | 2025-11-09 00:16:40.878993 | controller -> localhost | |O. . . . | 2025-11-09 00:16:40.879019 | controller -> localhost | |@* | 2025-11-09 00:16:40.879049 | controller -> localhost | +----[SHA256]-----+ 2025-11-09 00:16:40.879111 | controller -> localhost | ok: Runtime: 0:00:00.081330 2025-11-09 00:16:40.891122 | 2025-11-09 00:16:40.891221 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-09 00:16:40.924152 | controller | ok 2025-11-09 00:16:40.938812 | controller | included: /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-09 00:16:40.961057 | 2025-11-09 00:16:40.961253 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-09 00:16:40.986998 | controller | skipping: Conditional result was False 2025-11-09 00:16:40.994993 | 2025-11-09 00:16:40.995064 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-09 00:16:42.159893 | controller | changed 2025-11-09 00:16:42.176990 | 2025-11-09 00:16:42.177171 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-09 00:16:42.905088 | controller | ok 2025-11-09 00:16:42.917975 | 2025-11-09 00:16:42.918182 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-09 00:16:46.116603 | controller | changed 2025-11-09 00:16:46.136946 | 2025-11-09 00:16:46.137115 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-09 00:16:49.307891 | controller | changed 2025-11-09 00:16:49.316882 | 2025-11-09 00:16:49.316980 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-09 00:16:49.351949 | controller | skipping: Conditional result was False 2025-11-09 00:16:49.361352 | 2025-11-09 00:16:49.361452 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-09 00:16:49.855739 | controller -> localhost | changed 2025-11-09 00:16:49.874088 | 2025-11-09 00:16:49.874282 | TASK [add-build-sshkey : Add back temp key] 2025-11-09 00:16:50.206815 | controller -> localhost | Identity added: /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/work/23f7d198db3e4de2a2f3de1179514ed9_id_rsa (zuul-build-sshkey) 2025-11-09 00:16:50.207196 | controller -> localhost | ok: Runtime: 0:00:00.010745 2025-11-09 00:16:50.216605 | 2025-11-09 00:16:50.216715 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-09 00:16:51.181159 | controller | ok 2025-11-09 00:16:51.197298 | 2025-11-09 00:16:51.197440 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-09 00:16:51.235325 | controller | skipping: Conditional result was False 2025-11-09 00:16:51.262291 | 2025-11-09 00:16:51.262426 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-09 00:16:51.296955 | controller | ok 2025-11-09 00:16:51.319176 | 2025-11-09 00:16:51.319265 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-09 00:16:51.599129 | controller -> localhost | ok 2025-11-09 00:16:51.613545 | 2025-11-09 00:16:51.613720 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-09 00:16:51.655618 | controller | ok 2025-11-09 00:16:51.673568 | controller | included: /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-09 00:16:51.682088 | 2025-11-09 00:16:51.682178 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-09 00:16:52.033756 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-09 00:16:52.034106 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/work/23f7d198db3e4de2a2f3de1179514ed9_id_ecdsa. 2025-11-09 00:16:52.034171 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/work/23f7d198db3e4de2a2f3de1179514ed9_id_ecdsa.pub. 2025-11-09 00:16:52.034229 | controller -> localhost | The key fingerprint is: 2025-11-09 00:16:52.034273 | controller -> localhost | SHA256:j2I1hBMuf+dW5iDm0vRYDL3lhKeBOr4oSoLljyCTSvs zuul-build-sshkey 2025-11-09 00:16:52.034339 | controller -> localhost | The key's randomart image is: 2025-11-09 00:16:52.034383 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-09 00:16:52.034422 | controller -> localhost | | . | 2025-11-09 00:16:52.034461 | controller -> localhost | | . o o . | 2025-11-09 00:16:52.034500 | controller -> localhost | | . + + + + | 2025-11-09 00:16:52.034539 | controller -> localhost | | o + o O | 2025-11-09 00:16:52.034577 | controller -> localhost | | . + S B + | 2025-11-09 00:16:52.034616 | controller -> localhost | |.+ . O @ = | 2025-11-09 00:16:52.034654 | controller -> localhost | |Bo. = = = . | 2025-11-09 00:16:52.034780 | controller -> localhost | |*ooo o + . | 2025-11-09 00:16:52.034827 | controller -> localhost | |oooEo . | 2025-11-09 00:16:52.034869 | controller -> localhost | +----[SHA256]-----+ 2025-11-09 00:16:52.034963 | controller -> localhost | ok: Runtime: 0:00:00.016375 2025-11-09 00:16:52.050801 | 2025-11-09 00:16:52.050945 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-09 00:16:52.091658 | controller | ok 2025-11-09 00:16:52.110867 | controller | included: /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-09 00:16:52.156864 | 2025-11-09 00:16:52.157009 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-09 00:16:52.182213 | controller | skipping: Conditional result was False 2025-11-09 00:16:52.189336 | 2025-11-09 00:16:52.189400 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-09 00:16:53.189637 | controller | changed 2025-11-09 00:16:53.196003 | 2025-11-09 00:16:53.196077 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-09 00:16:53.894375 | controller | ok 2025-11-09 00:16:53.900793 | 2025-11-09 00:16:53.900873 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-09 00:16:57.016824 | controller | changed 2025-11-09 00:16:57.031252 | 2025-11-09 00:16:57.031413 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-09 00:17:00.130617 | controller | changed 2025-11-09 00:17:00.139055 | 2025-11-09 00:17:00.139148 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-09 00:17:00.175307 | controller | skipping: Conditional result was False 2025-11-09 00:17:00.184613 | 2025-11-09 00:17:00.184738 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-09 00:17:00.495242 | controller -> localhost | changed 2025-11-09 00:17:00.508371 | 2025-11-09 00:17:00.508460 | TASK [add-build-sshkey : Add back temp key] 2025-11-09 00:17:00.851389 | controller -> localhost | Identity added: /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/work/23f7d198db3e4de2a2f3de1179514ed9_id_ecdsa (zuul-build-sshkey) 2025-11-09 00:17:00.851911 | controller -> localhost | ok: Runtime: 0:00:00.013337 2025-11-09 00:17:00.868060 | 2025-11-09 00:17:00.868228 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-09 00:17:01.642568 | controller | ok 2025-11-09 00:17:01.655537 | 2025-11-09 00:17:01.655726 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-09 00:17:01.704234 | controller | skipping: Conditional result was False 2025-11-09 00:17:01.733048 | 2025-11-09 00:17:01.733225 | TASK [include_role : remove-zuul-sshkey] 2025-11-09 00:17:01.761444 | controller | skipping: Conditional result was False 2025-11-09 00:17:01.771194 | 2025-11-09 00:17:01.771303 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-09 00:17:02.464901 | controller | ok: "logs" 2025-11-09 00:17:02.465151 | controller | ok: All items complete 2025-11-09 00:17:02.465193 | 2025-11-09 00:17:03.137460 | controller | ok: "artifacts" 2025-11-09 00:17:03.809785 | controller | ok: "docs" 2025-11-09 00:17:03.827105 | 2025-11-09 00:17:03.827253 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-09 00:17:04.516890 | controller | changed: "logs" 2025-11-09 00:17:05.158733 | controller | changed: "artifacts" 2025-11-09 00:17:05.822830 | controller | changed: "docs" 2025-11-09 00:17:05.881544 | 2025-11-09 00:17:05.881649 | PLAY RECAP 2025-11-09 00:17:05.881746 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-09 00:17:05.881786 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-09 00:17:05.881812 | 2025-11-09 00:17:06.033885 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-09 00:17:06.034821 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-09 00:17:06.634637 | 2025-11-09 00:17:06.634804 | PLAY [all] 2025-11-09 00:17:06.657147 | 2025-11-09 00:17:06.657260 | TASK [Install binary dependencies] 2025-11-09 00:17:06.727606 | controller | ok 2025-11-09 00:17:06.747103 | 2025-11-09 00:17:06.747200 | TASK [bindep : Include find tasks] 2025-11-09 00:17:06.778479 | controller | ok 2025-11-09 00:17:06.788874 | controller | included: /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-09 00:17:06.797632 | 2025-11-09 00:17:06.797740 | TASK [bindep : Look for bindep.txt] 2025-11-09 00:17:07.834512 | controller | ok 2025-11-09 00:17:07.840511 | 2025-11-09 00:17:07.840589 | TASK [bindep : Define bindep_file fact] 2025-11-09 00:17:07.870438 | controller | skipping: Conditional result was False 2025-11-09 00:17:07.877373 | 2025-11-09 00:17:07.877455 | TASK [bindep : Look for other-requirements.txt] 2025-11-09 00:17:08.544966 | controller | ok 2025-11-09 00:17:08.558420 | 2025-11-09 00:17:08.558567 | TASK [bindep : Define bindep_file fact] 2025-11-09 00:17:08.596096 | controller | skipping: Conditional result was False 2025-11-09 00:17:08.610393 | 2025-11-09 00:17:08.610506 | TASK [bindep : Look for bindep fallback file] 2025-11-09 00:17:08.647141 | controller | skipping: Conditional result was False 2025-11-09 00:17:08.657005 | 2025-11-09 00:17:08.657109 | TASK [bindep : Define bindep_file fact] 2025-11-09 00:17:08.681254 | controller | skipping: Conditional result was False 2025-11-09 00:17:08.689149 | 2025-11-09 00:17:08.689243 | TASK [bindep : Include bindep tasks] 2025-11-09 00:17:08.712837 | controller | skipping: Conditional result was False 2025-11-09 00:17:08.722731 | 2025-11-09 00:17:08.722836 | TASK [bindep : Include install tasks] 2025-11-09 00:17:08.748036 | controller | skipping: Conditional result was False 2025-11-09 00:17:08.757786 | 2025-11-09 00:17:08.757890 | LOOP [bindep : Include package tasks] 2025-11-09 00:17:08.821458 | 2025-11-09 00:17:08.821728 | TASK [Run test-setup role] 2025-11-09 00:17:08.844326 | controller | ok 2025-11-09 00:17:08.871155 | 2025-11-09 00:17:08.871279 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-09 00:17:09.625445 | controller | ok 2025-11-09 00:17:09.631330 | 2025-11-09 00:17:09.631392 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-09 00:17:09.985971 | controller | skipping: Conditional result was False 2025-11-09 00:17:10.046097 | 2025-11-09 00:17:10.046276 | PLAY RECAP 2025-11-09 00:17:10.046343 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-09 00:17:10.046372 | 2025-11-09 00:17:10.226023 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-09 00:17:10.228090 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-09 00:17:10.871319 | 2025-11-09 00:17:10.871455 | PLAY [controller] 2025-11-09 00:17:10.893076 | 2025-11-09 00:17:10.893194 | TASK [Create the /root directory] 2025-11-09 00:17:11.948351 | controller | ok 2025-11-09 00:17:11.961500 | 2025-11-09 00:17:11.961662 | TASK [Install glibc-langpack-en] 2025-11-09 00:17:20.431650 | controller | ok: Nothing to do 2025-11-09 00:17:20.445427 | 2025-11-09 00:17:20.445610 | TASK [Ensure controller directory exists] 2025-11-09 00:17:21.274663 | controller | changed 2025-11-09 00:17:21.290773 | 2025-11-09 00:17:21.290953 | TASK [Install container runtime] 2025-11-09 00:17:21.343052 | controller | ok 2025-11-09 00:17:21.403560 | 2025-11-09 00:17:21.403740 | LOOP [ensure-podman : Find distribution installation] 2025-11-09 00:17:21.444550 | controller | ok: "/var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-09 00:17:21.457705 | controller | included: /var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-09 00:17:21.464610 | 2025-11-09 00:17:21.464705 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-09 00:19:28.884587 | controller | changed 2025-11-09 00:19:28.898517 | 2025-11-09 00:19:28.898645 | TASK [ensure-podman : Fetch podman version] 2025-11-09 00:19:30.089739 | controller | Client: Podman Engine 2025-11-09 00:19:30.139992 | controller | Version: 4.6.2 2025-11-09 00:19:30.140085 | controller | API Version: 4.6.2 2025-11-09 00:19:30.140094 | controller | Go Version: go1.19.12 2025-11-09 00:19:30.140122 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-09 00:19:30.140132 | controller | OS/Arch: linux/amd64 2025-11-09 00:19:30.287448 | controller | ok: Runtime: 0:00:00.319633 2025-11-09 00:19:30.300958 | 2025-11-09 00:19:30.301098 | TASK [ensure-podman : Print podman version installed] 2025-11-09 00:19:30.352892 | Podman version: Client: Podman Engine 2025-11-09 00:19:30.353321 | Version: 4.6.2 2025-11-09 00:19:30.353394 | API Version: 4.6.2 2025-11-09 00:19:30.353440 | Go Version: go1.19.12 2025-11-09 00:19:30.353480 | Built: Mon Aug 28 19:38:31 2023 2025-11-09 00:19:30.353524 | OS/Arch: linux/amd64 2025-11-09 00:19:30.366425 | 2025-11-09 00:19:30.366607 | TASK [ensure-podman : Validate podman engine] 2025-11-09 00:19:30.731771 | controller | skipping: Conditional result was False 2025-11-09 00:19:30.747558 | 2025-11-09 00:19:30.747766 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-09 00:19:30.777873 | controller | skipping: Conditional result was False 2025-11-09 00:19:30.803112 | 2025-11-09 00:19:30.803259 | TASK [Ensure python3.8 is present] 2025-11-09 00:19:30.832935 | controller | skipping: Conditional result was False 2025-11-09 00:19:30.843880 | 2025-11-09 00:19:30.843975 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-09 00:19:30.870145 | controller | ok 2025-11-09 00:19:30.898649 | 2025-11-09 00:19:30.898782 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-09 00:19:34.296055 | controller | ok: Nothing to do 2025-11-09 00:19:34.309905 | 2025-11-09 00:19:34.310055 | TASK [our-ensure-python : Also install python3-devel] 2025-11-09 00:19:48.330218 | controller | changed 2025-11-09 00:19:48.354288 | 2025-11-09 00:19:48.354426 | TASK [Run ensure-virtualenv role] 2025-11-09 00:19:48.392383 | controller | ok 2025-11-09 00:19:48.428885 | 2025-11-09 00:19:48.428983 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-09 00:19:49.252010 | controller | /usr/bin/virtualenv 2025-11-09 00:19:49.792864 | controller | ok: Runtime: 0:00:00.004951 2025-11-09 00:19:49.805811 | 2025-11-09 00:19:49.805935 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-09 00:19:49.845869 | controller | skipping: Conditional result was False 2025-11-09 00:19:49.846426 | controller | ok: All items complete 2025-11-09 00:19:49.846490 | 2025-11-09 00:19:49.872367 | 2025-11-09 00:19:49.872508 | TASK [Find the full path of the Python interpreter] 2025-11-09 00:19:50.711620 | controller | /usr/bin/python3 2025-11-09 00:19:51.281796 | controller | ok 2025-11-09 00:19:51.287649 | 2025-11-09 00:19:51.287870 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-09 00:19:53.034984 | controller | created virtual environment CPython3.11.0.final.0-64 in 853ms 2025-11-09 00:19:53.109373 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-09 00:19:53.109424 | 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-09 00:19:53.109439 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-09 00:19:53.109457 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-09 00:19:53.648232 | controller | changed 2025-11-09 00:19:53.660979 | 2025-11-09 00:19:53.661117 | TASK [Set selinux package] 2025-11-09 00:19:53.700175 | controller | ok 2025-11-09 00:19:53.711745 | 2025-11-09 00:19:53.711878 | TASK [Set selinux package (Fedora)] 2025-11-09 00:19:53.761615 | controller | ok 2025-11-09 00:19:53.773271 | 2025-11-09 00:19:53.773408 | TASK [Install selinux into virtualenv] 2025-11-09 00:19:56.931784 | controller | Collecting selinux-please-lie-to-me 2025-11-09 00:19:57.000574 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-09 00:19:57.528121 | controller | Collecting setuptools<50.0.0 2025-11-09 00:19:57.534068 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-09 00:19:57.585743 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 17.2 MB/s eta 0:00:00 2025-11-09 00:19:57.731800 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-09 00:19:57.732114 | controller | Attempting uninstall: setuptools 2025-11-09 00:19:57.735738 | controller | Found existing installation: setuptools 62.6.0 2025-11-09 00:19:57.841109 | controller | Uninstalling setuptools-62.6.0: 2025-11-09 00:19:57.853902 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-09 00:19:58.592028 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-09 00:19:58.819378 | controller | 2025-11-09 00:19:59.066113 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-09 00:19:59.066170 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-09 00:19:59.668383 | controller | ok: Runtime: 0:00:04.473957 2025-11-09 00:19:59.681643 | 2025-11-09 00:19:59.681869 | TASK [Install pytest-forked into virtualenv] 2025-11-09 00:20:01.202601 | controller | Collecting pytest-forked 2025-11-09 00:20:01.265963 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-09 00:20:01.334933 | controller | Collecting py 2025-11-09 00:20:01.338904 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-09 00:20:01.373626 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00 2025-11-09 00:20:01.575777 | controller | Collecting pytest>=3.10 2025-11-09 00:20:01.583240 | controller | Downloading pytest-9.0.0-py3-none-any.whl (373 kB) 2025-11-09 00:20:01.609036 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 373.4/373.4 kB 19.1 MB/s eta 0:00:00 2025-11-09 00:20:01.692801 | controller | Collecting iniconfig>=1.0.1 2025-11-09 00:20:01.698185 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-09 00:20:01.773790 | controller | Collecting packaging>=22 2025-11-09 00:20:01.779626 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-09 00:20:01.793717 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 7.2 MB/s eta 0:00:00 2025-11-09 00:20:01.842929 | controller | Collecting pluggy<2,>=1.5 2025-11-09 00:20:01.847291 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-09 00:20:01.929089 | controller | Collecting pygments>=2.7.2 2025-11-09 00:20:01.934729 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-09 00:20:01.963538 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 47.9 MB/s eta 0:00:00 2025-11-09 00:20:02.110114 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-09 00:20:04.583428 | 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.0 pytest-forked-1.6.0 2025-11-09 00:20:04.600483 | controller | 2025-11-09 00:20:04.870215 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-09 00:20:04.870273 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-09 00:20:05.073253 | controller | ok: Runtime: 0:00:04.381063 2025-11-09 00:20:05.087153 | 2025-11-09 00:20:05.087300 | TASK [Update pip] 2025-11-09 00:20:06.523817 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-09 00:20:06.799110 | controller | Collecting pip 2025-11-09 00:20:06.882200 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-09 00:20:06.960017 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 26.9 MB/s eta 0:00:00 2025-11-09 00:20:07.099002 | controller | Installing collected packages: pip 2025-11-09 00:20:07.099316 | controller | Attempting uninstall: pip 2025-11-09 00:20:07.105200 | controller | Found existing installation: pip 22.2.2 2025-11-09 00:20:07.413797 | controller | Uninstalling pip-22.2.2: 2025-11-09 00:20:07.444695 | controller | Successfully uninstalled pip-22.2.2 2025-11-09 00:20:09.441850 | controller | Successfully installed pip-25.3 2025-11-09 00:20:09.970252 | controller | ok: Runtime: 0:00:03.767159 2025-11-09 00:20:09.984261 | 2025-11-09 00:20:09.984423 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-09 00:20:10.913515 | controller | changed 2025-11-09 00:20:10.925294 | 2025-11-09 00:20:10.925438 | TASK [Install ansible into virtualenv] 2025-11-09 00:20:12.277938 | controller | Processing ./src/github.com/ansible/ansible 2025-11-09 00:20:12.289420 | controller | Installing build dependencies: started 2025-11-09 00:20:14.113139 | controller | Installing build dependencies: finished with status 'done' 2025-11-09 00:20:14.114806 | controller | Getting requirements to build wheel: started 2025-11-09 00:20:15.731941 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-09 00:20:15.733696 | controller | Preparing metadata (pyproject.toml): started 2025-11-09 00:20:16.630333 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-09 00:20:16.635484 | 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-09 00:20:16.640929 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-09 00:20:17.329946 | controller | ERROR 2025-11-09 00:20:17.330378 | controller | { 2025-11-09 00:20:17.330595 | controller | "delta": "0:00:05.121650", 2025-11-09 00:20:17.330657 | controller | "end": "2025-11-09 00:20:16.800730", 2025-11-09 00:20:17.330739 | controller | "msg": "non-zero return code", 2025-11-09 00:20:17.330808 | controller | "rc": 1, 2025-11-09 00:20:17.330849 | controller | "start": "2025-11-09 00:20:11.679080" 2025-11-09 00:20:17.330888 | controller | } failure 2025-11-09 00:20:17.334142 | 2025-11-09 00:20:17.334414 | PLAY RECAP 2025-11-09 00:20:17.334524 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-09 00:20:17.334583 | 2025-11-09 00:20:17.494873 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-09 00:20:17.497186 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-09 00:20:18.136408 | 2025-11-09 00:20:18.136597 | PLAY [all] 2025-11-09 00:20:18.160619 | 2025-11-09 00:20:18.160751 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-09 00:20:20.047387 | controller | changed: non-zero return code 2025-11-09 00:20:20.056661 | 2025-11-09 00:20:20.056821 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-09 00:20:20.084671 | controller | skipping: Conditional result was False 2025-11-09 00:20:20.100249 | 2025-11-09 00:20:20.100543 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-09 00:20:20.155576 | 2025-11-09 00:20:20.155919 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-09 00:20:20.199224 | 2025-11-09 00:20:20.199558 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-09 00:20:20.227943 | controller | skipping: Conditional result was False 2025-11-09 00:20:20.241888 | 2025-11-09 00:20:20.242171 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-09 00:20:20.282243 | 2025-11-09 00:20:20.282558 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-09 00:20:20.309092 | controller | skipping: Conditional result was False 2025-11-09 00:20:20.322460 | 2025-11-09 00:20:20.322616 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-09 00:20:20.349055 | controller | skipping: Conditional result was False 2025-11-09 00:20:20.362501 | 2025-11-09 00:20:20.362656 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-09 00:20:20.389181 | controller | skipping: Conditional result was False 2025-11-09 00:20:20.426194 | 2025-11-09 00:20:20.426301 | PLAY RECAP 2025-11-09 00:20:20.426353 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-09 00:20:20.426380 | 2025-11-09 00:20:20.567188 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-09 00:20:20.569001 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-09 00:20:21.240914 | 2025-11-09 00:20:21.241082 | PLAY [all:!appliance*] 2025-11-09 00:20:21.264189 | 2025-11-09 00:20:21.264318 | TASK [unregister the node] 2025-11-09 00:20:21.619169 | controller | skipping: Conditional result was False 2025-11-09 00:20:21.632011 | 2025-11-09 00:20:21.632179 | TASK [include_role : fetch-output] 2025-11-09 00:20:21.681357 | controller | ok 2025-11-09 00:20:21.721014 | 2025-11-09 00:20:21.721184 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-09 00:20:21.798878 | controller | skipping: Conditional result was False 2025-11-09 00:20:21.813605 | 2025-11-09 00:20:21.813793 | TASK [fetch-output : Set log path for single node] 2025-11-09 00:20:21.864283 | controller | ok 2025-11-09 00:20:21.876839 | 2025-11-09 00:20:21.876935 | LOOP [fetch-output : Ensure local output dirs] 2025-11-09 00:20:22.365559 | controller -> localhost | ok: "/var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/work/logs" 2025-11-09 00:20:22.587008 | controller -> localhost | changed: "/var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/work/artifacts" 2025-11-09 00:20:22.835061 | controller -> localhost | changed: "/var/lib/zuul/builds/23f7d198db3e4de2a2f3de1179514ed9/work/docs" 2025-11-09 00:20:22.849934 | 2025-11-09 00:20:22.850113 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-09 00:20:25.177462 | controller | changed: 2025-11-09 00:20:25.177884 | controller | .d..t...... ./ 2025-11-09 00:20:25.177949 | controller | cd+++++++++ controller/ 2025-11-09 00:20:25.178021 | controller | changed: All items complete 2025-11-09 00:20:25.178067 | 2025-11-09 00:20:27.296996 | controller | changed: .d..t...... ./ 2025-11-09 00:20:29.401985 | controller | changed: .d..t...... ./ 2025-11-09 00:20:29.425538 | 2025-11-09 00:20:29.425759 | TASK [include_role : fetch-output-openshift] 2025-11-09 00:20:29.453219 | controller | skipping: Conditional result was False 2025-11-09 00:20:29.465994 | 2025-11-09 00:20:29.466425 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-09 00:20:29.527358 | controller | skipping: Conditional result was False 2025-11-09 00:20:29.536165 | controller | skipping: Conditional result was False 2025-11-09 00:20:29.588956 | 2025-11-09 00:20:29.589095 | PLAY [localhost] 2025-11-09 00:20:29.608608 | 2025-11-09 00:20:29.608803 | TASK [Run Zuul manifest role] 2025-11-09 00:20:29.629076 | localhost | ok 2025-11-09 00:20:29.642866 | 2025-11-09 00:20:29.642948 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-09 00:20:30.052032 | localhost | changed 2025-11-09 00:20:30.059467 | 2025-11-09 00:20:30.059586 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-09 00:20:30.114342 | localhost | ok 2025-11-09 00:20:30.128308 | 2025-11-09 00:20:30.128414 | TASK [Set zuul-log-path fact] 2025-11-09 00:20:30.200333 | localhost | ok 2025-11-09 00:20:30.219404 | 2025-11-09 00:20:30.219548 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-09 00:20:30.260140 | localhost | ok 2025-11-09 00:20:30.268211 | 2025-11-09 00:20:30.268272 | LOOP [Run upload-logs-swift role] 2025-11-09 00:20:30.314218 | localhost | Output suppressed because no_log was given 2025-11-09 00:20:30.342436 | 2025-11-09 00:20:30.342501 | TASK [Set zuul-log-path fact] 2025-11-09 00:20:30.387740 | localhost | skipping: Conditional result was False 2025-11-09 00:20:30.393330 | 2025-11-09 00:20:30.393394 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-09 00:20:30.957776 | localhost -> localhost | ok: Runtime: 0:00:00.011584 2025-11-09 00:20:30.963878 | 2025-11-09 00:20:30.963943 | TASK [upload-logs-swift : Upload logs to swift]