2025-12-24 00:19:43.204672 | Job console starting... 2025-12-24 00:19:43.216296 | Updating repositories 2025-12-24 00:19:43.399595 | Preparing job workspace 2025-12-24 00:19:47.384342 | Running Ansible setup... 2025-12-24 00:19:51.856439 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-24 00:19:52.417574 | 2025-12-24 00:19:52.417688 | PLAY [localhost] 2025-12-24 00:19:52.425797 | 2025-12-24 00:19:52.425864 | TASK [Gathering Facts] 2025-12-24 00:19:53.405604 | localhost | ok 2025-12-24 00:19:53.424415 | 2025-12-24 00:19:53.424532 | TASK [Setup log path fact] 2025-12-24 00:19:53.444105 | localhost | ok 2025-12-24 00:19:53.460814 | 2025-12-24 00:19:53.460905 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-24 00:19:53.490353 | localhost | ok 2025-12-24 00:19:53.500691 | 2025-12-24 00:19:53.500779 | TASK [emit-job-header : Print job information] 2025-12-24 00:19:53.540274 | # Job Information 2025-12-24 00:19:53.540413 | Ansible Version: 2.15.12 2025-12-24 00:19:53.540467 | Job: ansible-test-sanity-docker-milestone 2025-12-24 00:19:53.540497 | Pipeline: periodic 2025-12-24 00:19:53.540522 | Executor: ze01.softwarefactory-project.io 2025-12-24 00:19:53.540546 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-24 00:19:53.540574 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/ef6/ansible/ef626e746d5c4bf3b8143fb8bc108548/ 2025-12-24 00:19:53.540599 | Event ID: 444a083e8b1242a295732fab2106314a 2025-12-24 00:19:53.545535 | 2025-12-24 00:19:53.545618 | LOOP [emit-job-header : Print node information] 2025-12-24 00:19:53.656187 | localhost | ok: 2025-12-24 00:19:53.656476 | localhost | # Node Information 2025-12-24 00:19:53.656536 | localhost | Inventory Hostname: controller 2025-12-24 00:19:53.656577 | localhost | Hostname: np0005569796 2025-12-24 00:19:53.656617 | localhost | Username: zuul 2025-12-24 00:19:53.656663 | localhost | Distro: Fedora 37 2025-12-24 00:19:53.656703 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-24 00:19:53.656740 | localhost | Region: ca-ymq-1 2025-12-24 00:19:53.656776 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-24 00:19:53.656812 | localhost | Product Name: OpenStack Nova 2025-12-24 00:19:53.656847 | localhost | Interface IP: 162.253.55.231 2025-12-24 00:19:53.678699 | 2025-12-24 00:19:53.678871 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-24 00:19:54.122996 | localhost -> localhost | changed 2025-12-24 00:19:54.140497 | 2025-12-24 00:19:54.140918 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-24 00:19:55.077286 | localhost -> localhost | changed 2025-12-24 00:19:55.119664 | 2025-12-24 00:19:55.119784 | PLAY [all:!appliance*] 2025-12-24 00:19:55.150897 | 2025-12-24 00:19:55.150991 | TASK [include_role : start-zuul-console] 2025-12-24 00:19:55.173645 | controller | ok 2025-12-24 00:19:55.192653 | 2025-12-24 00:19:55.192738 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-24 00:19:55.617641 | controller | ok 2025-12-24 00:19:55.641477 | 2025-12-24 00:19:55.641612 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-24 00:20:29.886905 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-24 00:20:29.904888 | 2025-12-24 00:20:29.905006 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-24 00:20:30.436474 | controller | skipping: Conditional result was False 2025-12-24 00:20:30.443317 | 2025-12-24 00:20:30.443390 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-24 00:20:30.467687 | controller | skipping: Conditional result was False 2025-12-24 00:20:30.474876 | 2025-12-24 00:20:30.474964 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-24 00:20:30.499304 | controller | skipping: Conditional result was False 2025-12-24 00:20:30.518452 | 2025-12-24 00:20:30.518685 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-24 00:20:30.546692 | controller | skipping: Conditional result was False 2025-12-24 00:20:30.557059 | 2025-12-24 00:20:30.557181 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-24 00:20:30.582258 | controller | skipping: Conditional result was False 2025-12-24 00:20:30.591147 | 2025-12-24 00:20:30.591247 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-24 00:20:30.616278 | controller | skipping: Conditional result was False 2025-12-24 00:20:30.629593 | 2025-12-24 00:20:30.629685 | TASK [Disable Fedora Modular] 2025-12-24 00:20:30.863995 | controller | changed 2025-12-24 00:20:30.869781 | 2025-12-24 00:20:30.869843 | TASK [Enable EPEL] 2025-12-24 00:20:30.884257 | controller | skipping: Conditional result was False 2025-12-24 00:20:30.890947 | 2025-12-24 00:20:30.891050 | TASK [Register the RHEL node] 2025-12-24 00:20:31.439374 | 2025-12-24 00:20:31.439633 | TASK [Show the subscription-manager status] 2025-12-24 00:20:31.993401 | controller | skipping: Conditional result was False 2025-12-24 00:20:32.000241 | 2025-12-24 00:20:32.000306 | TASK [Enable EPEL on RHEL] 2025-12-24 00:20:32.536138 | controller | skipping: Conditional result was False 2025-12-24 00:20:32.543864 | 2025-12-24 00:20:32.543988 | TASK [Install git and tox] 2025-12-24 00:21:20.904153 | controller | changed 2025-12-24 00:21:20.911696 | 2025-12-24 00:21:20.911862 | TASK [include_role : prepare-workspace] 2025-12-24 00:21:20.945370 | controller | ok 2025-12-24 00:21:20.967717 | 2025-12-24 00:21:20.967853 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-24 00:21:21.233882 | controller | ok 2025-12-24 00:21:21.245132 | 2025-12-24 00:21:21.245322 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-24 00:21:33.604191 | controller | Output suppressed because no_log was given 2025-12-24 00:21:33.624360 | 2025-12-24 00:21:33.624494 | TASK [include_role : prepare-workspace-openshift] 2025-12-24 00:21:33.641895 | controller | skipping: Conditional result was False 2025-12-24 00:21:33.717635 | 2025-12-24 00:21:33.717731 | PLAY [all:!appliance] 2025-12-24 00:21:33.740838 | 2025-12-24 00:21:33.740921 | TASK [Run add-build-sshkey role (RSA)] 2025-12-24 00:21:33.772369 | controller | ok 2025-12-24 00:21:33.792619 | 2025-12-24 00:21:33.792736 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-24 00:21:34.030545 | controller -> localhost | ok 2025-12-24 00:21:34.037589 | 2025-12-24 00:21:34.037729 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-24 00:21:34.068851 | controller | ok 2025-12-24 00:21:34.082587 | controller | included: /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-24 00:21:34.088672 | 2025-12-24 00:21:34.088732 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-24 00:21:34.705207 | controller -> localhost | Generating public/private rsa key pair. 2025-12-24 00:21:34.705577 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/work/ef626e746d5c4bf3b8143fb8bc108548_id_rsa. 2025-12-24 00:21:34.705638 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/work/ef626e746d5c4bf3b8143fb8bc108548_id_rsa.pub. 2025-12-24 00:21:34.705682 | controller -> localhost | The key fingerprint is: 2025-12-24 00:21:34.705724 | controller -> localhost | SHA256:8J6ltfwrKLj0/DLNvDlLKIuB839+sZmjE7GN8cEMbUU zuul-build-sshkey 2025-12-24 00:21:34.705763 | controller -> localhost | The key's randomart image is: 2025-12-24 00:21:34.705801 | controller -> localhost | +---[RSA 2048]----+ 2025-12-24 00:21:34.705839 | controller -> localhost | | . oE | 2025-12-24 00:21:34.705878 | controller -> localhost | | . o | 2025-12-24 00:21:34.706002 | controller -> localhost | | .= | 2025-12-24 00:21:34.706075 | controller -> localhost | | oo+ | 2025-12-24 00:21:34.706114 | controller -> localhost | | BS.o | 2025-12-24 00:21:34.706168 | controller -> localhost | | . +o+* . | 2025-12-24 00:21:34.706218 | controller -> localhost | |o . o..==*o | 2025-12-24 00:21:34.706260 | controller -> localhost | | o +.=*.%... | 2025-12-24 00:21:34.706298 | controller -> localhost | | o.++=O== .o. | 2025-12-24 00:21:34.706341 | controller -> localhost | +----[SHA256]-----+ 2025-12-24 00:21:34.706433 | controller -> localhost | ok: Runtime: 0:00:00.092202 2025-12-24 00:21:34.721393 | 2025-12-24 00:21:34.721525 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-24 00:21:34.760921 | controller | ok 2025-12-24 00:21:34.785754 | controller | included: /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-24 00:21:34.800065 | 2025-12-24 00:21:34.800176 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-24 00:21:34.825110 | controller | skipping: Conditional result was False 2025-12-24 00:21:34.833087 | 2025-12-24 00:21:34.833173 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-24 00:21:35.268806 | controller | changed 2025-12-24 00:21:35.278812 | 2025-12-24 00:21:35.279090 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-24 00:21:35.510556 | controller | ok 2025-12-24 00:21:35.520809 | 2025-12-24 00:21:35.520925 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-24 00:21:36.127589 | controller | changed 2025-12-24 00:21:36.134017 | 2025-12-24 00:21:36.134103 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-24 00:21:36.730903 | controller | changed 2025-12-24 00:21:36.739601 | 2025-12-24 00:21:36.739698 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-24 00:21:36.765473 | controller | skipping: Conditional result was False 2025-12-24 00:21:36.775898 | 2025-12-24 00:21:36.776054 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-24 00:21:37.168294 | controller -> localhost | changed 2025-12-24 00:21:37.180752 | 2025-12-24 00:21:37.180842 | TASK [add-build-sshkey : Add back temp key] 2025-12-24 00:21:37.471253 | controller -> localhost | Identity added: /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/work/ef626e746d5c4bf3b8143fb8bc108548_id_rsa (zuul-build-sshkey) 2025-12-24 00:21:37.471659 | controller -> localhost | ok: Runtime: 0:00:00.013131 2025-12-24 00:21:37.487516 | 2025-12-24 00:21:37.487653 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-24 00:21:37.828102 | controller | ok 2025-12-24 00:21:37.833530 | 2025-12-24 00:21:37.833599 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-24 00:21:37.868571 | controller | skipping: Conditional result was False 2025-12-24 00:21:37.886737 | 2025-12-24 00:21:37.886918 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-24 00:21:37.925269 | controller | ok 2025-12-24 00:21:37.950124 | 2025-12-24 00:21:37.950378 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-24 00:21:38.220868 | controller -> localhost | ok 2025-12-24 00:21:38.227890 | 2025-12-24 00:21:38.227963 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-24 00:21:38.258792 | controller | ok 2025-12-24 00:21:38.269659 | controller | included: /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-24 00:21:38.276502 | 2025-12-24 00:21:38.276677 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-24 00:21:38.559963 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-24 00:21:38.560249 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/work/ef626e746d5c4bf3b8143fb8bc108548_id_ecdsa. 2025-12-24 00:21:38.560293 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/work/ef626e746d5c4bf3b8143fb8bc108548_id_ecdsa.pub. 2025-12-24 00:21:38.560337 | controller -> localhost | The key fingerprint is: 2025-12-24 00:21:38.560368 | controller -> localhost | SHA256:TdD2SA0vRHgrjTZinlYJAqp6gDJRjxro2ekg1vRqnk0 zuul-build-sshkey 2025-12-24 00:21:38.560397 | controller -> localhost | The key's randomart image is: 2025-12-24 00:21:38.560423 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-24 00:21:38.560445 | controller -> localhost | | o. .++o | 2025-12-24 00:21:38.560467 | controller -> localhost | |.o o. . .o=.. | 2025-12-24 00:21:38.560489 | controller -> localhost | |= .... . Bo+. | 2025-12-24 00:21:38.560511 | controller -> localhost | |++= o o Bo+.. | 2025-12-24 00:21:38.560533 | controller -> localhost | |O= + + =So. | 2025-12-24 00:21:38.560554 | controller -> localhost | |=oo . + | 2025-12-24 00:21:38.560575 | controller -> localhost | |. .+ E | 2025-12-24 00:21:38.560597 | controller -> localhost | | .o + | 2025-12-24 00:21:38.560619 | controller -> localhost | | o . | 2025-12-24 00:21:38.560642 | controller -> localhost | +----[SHA256]-----+ 2025-12-24 00:21:38.560707 | controller -> localhost | ok: Runtime: 0:00:00.014907 2025-12-24 00:21:38.570623 | 2025-12-24 00:21:38.570750 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-24 00:21:38.595726 | controller | ok 2025-12-24 00:21:38.606766 | controller | included: /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-24 00:21:38.620424 | 2025-12-24 00:21:38.620533 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-24 00:21:38.635660 | controller | skipping: Conditional result was False 2025-12-24 00:21:38.643622 | 2025-12-24 00:21:38.643709 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-24 00:21:38.915511 | controller | changed 2025-12-24 00:21:38.929203 | 2025-12-24 00:21:38.929432 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-24 00:21:39.185481 | controller | ok 2025-12-24 00:21:39.198861 | 2025-12-24 00:21:39.199003 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-24 00:21:39.839558 | controller | changed 2025-12-24 00:21:39.845510 | 2025-12-24 00:21:39.845579 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-24 00:21:40.507412 | controller | changed 2025-12-24 00:21:40.521639 | 2025-12-24 00:21:40.521785 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-24 00:21:40.550627 | controller | skipping: Conditional result was False 2025-12-24 00:21:40.605886 | 2025-12-24 00:21:40.606083 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-24 00:21:40.908144 | controller -> localhost | changed 2025-12-24 00:21:40.920139 | 2025-12-24 00:21:40.920253 | TASK [add-build-sshkey : Add back temp key] 2025-12-24 00:21:41.220079 | controller -> localhost | Identity added: /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/work/ef626e746d5c4bf3b8143fb8bc108548_id_ecdsa (zuul-build-sshkey) 2025-12-24 00:21:41.220331 | controller -> localhost | ok: Runtime: 0:00:00.007459 2025-12-24 00:21:41.227293 | 2025-12-24 00:21:41.227388 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-24 00:21:41.430533 | controller | ok 2025-12-24 00:21:41.437877 | 2025-12-24 00:21:41.437979 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-24 00:21:41.462592 | controller | skipping: Conditional result was False 2025-12-24 00:21:41.474705 | 2025-12-24 00:21:41.474835 | TASK [include_role : remove-zuul-sshkey] 2025-12-24 00:21:41.500120 | controller | skipping: Conditional result was False 2025-12-24 00:21:41.507395 | 2025-12-24 00:21:41.507510 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-24 00:21:41.724707 | controller | ok: "logs" 2025-12-24 00:21:41.725119 | controller | ok: All items complete 2025-12-24 00:21:41.725176 | 2025-12-24 00:21:41.911575 | controller | ok: "artifacts" 2025-12-24 00:21:42.109720 | controller | ok: "docs" 2025-12-24 00:21:42.126277 | 2025-12-24 00:21:42.126384 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-24 00:21:42.365499 | controller | changed: "logs" 2025-12-24 00:21:42.567721 | controller | changed: "artifacts" 2025-12-24 00:21:42.751314 | controller | changed: "docs" 2025-12-24 00:21:42.795085 | 2025-12-24 00:21:42.795193 | PLAY RECAP 2025-12-24 00:21:42.795247 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-24 00:21:42.795285 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-24 00:21:42.795312 | 2025-12-24 00:21:42.911411 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-24 00:21:42.912270 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-24 00:21:43.514253 | 2025-12-24 00:21:43.514378 | PLAY [all] 2025-12-24 00:21:43.538537 | 2025-12-24 00:21:43.538665 | TASK [Install binary dependencies] 2025-12-24 00:21:43.590966 | controller | ok 2025-12-24 00:21:43.613662 | 2025-12-24 00:21:43.613790 | TASK [bindep : Include find tasks] 2025-12-24 00:21:43.653651 | controller | ok 2025-12-24 00:21:43.661725 | controller | included: /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-24 00:21:43.667983 | 2025-12-24 00:21:43.668066 | TASK [bindep : Look for bindep.txt] 2025-12-24 00:21:44.023264 | controller | ok 2025-12-24 00:21:44.029572 | 2025-12-24 00:21:44.029650 | TASK [bindep : Define bindep_file fact] 2025-12-24 00:21:44.053236 | controller | skipping: Conditional result was False 2025-12-24 00:21:44.059551 | 2025-12-24 00:21:44.059628 | TASK [bindep : Look for other-requirements.txt] 2025-12-24 00:21:44.262325 | controller | ok 2025-12-24 00:21:44.267857 | 2025-12-24 00:21:44.267933 | TASK [bindep : Define bindep_file fact] 2025-12-24 00:21:44.302605 | controller | skipping: Conditional result was False 2025-12-24 00:21:44.312631 | 2025-12-24 00:21:44.312757 | TASK [bindep : Look for bindep fallback file] 2025-12-24 00:21:44.348454 | controller | skipping: Conditional result was False 2025-12-24 00:21:44.359566 | 2025-12-24 00:21:44.359679 | TASK [bindep : Define bindep_file fact] 2025-12-24 00:21:44.395571 | controller | skipping: Conditional result was False 2025-12-24 00:21:44.404822 | 2025-12-24 00:21:44.404927 | TASK [bindep : Include bindep tasks] 2025-12-24 00:21:44.440267 | controller | skipping: Conditional result was False 2025-12-24 00:21:44.449419 | 2025-12-24 00:21:44.449523 | TASK [bindep : Include install tasks] 2025-12-24 00:21:44.485495 | controller | skipping: Conditional result was False 2025-12-24 00:21:44.495724 | 2025-12-24 00:21:44.495903 | LOOP [bindep : Include package tasks] 2025-12-24 00:21:44.591008 | 2025-12-24 00:21:44.591238 | TASK [Run test-setup role] 2025-12-24 00:21:44.617087 | controller | ok 2025-12-24 00:21:44.643039 | 2025-12-24 00:21:44.643228 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-24 00:21:44.885138 | controller | ok 2025-12-24 00:21:44.898829 | 2025-12-24 00:21:44.898967 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-24 00:21:45.449562 | controller | skipping: Conditional result was False 2025-12-24 00:21:45.508268 | 2025-12-24 00:21:45.508397 | PLAY RECAP 2025-12-24 00:21:45.508451 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-24 00:21:45.508481 | 2025-12-24 00:21:45.643535 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-24 00:21:45.644407 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-24 00:21:46.245514 | 2025-12-24 00:21:46.245680 | PLAY [controller] 2025-12-24 00:21:46.267190 | 2025-12-24 00:21:46.267413 | TASK [Create the /root directory] 2025-12-24 00:21:46.624015 | controller | ok 2025-12-24 00:21:46.633458 | 2025-12-24 00:21:46.633538 | TASK [Install glibc-langpack-en] 2025-12-24 00:21:50.616518 | controller | ok: Nothing to do 2025-12-24 00:21:50.635144 | 2025-12-24 00:21:50.635401 | TASK [Ensure controller directory exists] 2025-12-24 00:21:50.833974 | controller | changed 2025-12-24 00:21:50.842569 | 2025-12-24 00:21:50.842649 | TASK [Install container runtime] 2025-12-24 00:21:50.896677 | controller | ok 2025-12-24 00:21:50.951568 | 2025-12-24 00:21:50.951779 | LOOP [ensure-podman : Find distribution installation] 2025-12-24 00:21:50.990214 | controller | ok: "/var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-24 00:21:51.010209 | controller | included: /var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-24 00:21:51.017087 | 2025-12-24 00:21:51.017157 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-24 00:22:55.692878 | controller | changed 2025-12-24 00:22:55.699925 | 2025-12-24 00:22:55.699990 | TASK [ensure-podman : Fetch podman version] 2025-12-24 00:22:56.239921 | controller | Client: Podman Engine 2025-12-24 00:22:56.240016 | controller | Version: 4.6.2 2025-12-24 00:22:56.240061 | controller | API Version: 4.6.2 2025-12-24 00:22:56.240101 | controller | Go Version: go1.19.12 2025-12-24 00:22:56.240151 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-24 00:22:56.240192 | controller | OS/Arch: linux/amd64 2025-12-24 00:22:56.754263 | controller | ok: Runtime: 0:00:00.206234 2025-12-24 00:22:56.772313 | 2025-12-24 00:22:56.772504 | TASK [ensure-podman : Print podman version installed] 2025-12-24 00:22:56.812245 | Podman version: Client: Podman Engine 2025-12-24 00:22:56.812533 | Version: 4.6.2 2025-12-24 00:22:56.812623 | API Version: 4.6.2 2025-12-24 00:22:56.812694 | Go Version: go1.19.12 2025-12-24 00:22:56.812744 | Built: Mon Aug 28 19:38:31 2023 2025-12-24 00:22:56.812789 | OS/Arch: linux/amd64 2025-12-24 00:22:56.826338 | 2025-12-24 00:22:56.826506 | TASK [ensure-podman : Validate podman engine] 2025-12-24 00:22:57.371571 | controller | skipping: Conditional result was False 2025-12-24 00:22:57.385959 | 2025-12-24 00:22:57.386146 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-24 00:22:57.403003 | controller | skipping: Conditional result was False 2025-12-24 00:22:57.416849 | 2025-12-24 00:22:57.416957 | TASK [Ensure python3.8 is present] 2025-12-24 00:22:57.441814 | controller | skipping: Conditional result was False 2025-12-24 00:22:57.448756 | 2025-12-24 00:22:57.448824 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-24 00:22:57.470587 | controller | ok 2025-12-24 00:22:57.491150 | 2025-12-24 00:22:57.491233 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-24 00:22:59.009418 | controller | ok: Nothing to do 2025-12-24 00:22:59.016408 | 2025-12-24 00:22:59.016550 | TASK [our-ensure-python : Also install python3-devel] 2025-12-24 00:23:08.752365 | controller | changed 2025-12-24 00:23:08.770813 | 2025-12-24 00:23:08.770921 | TASK [Run ensure-virtualenv role] 2025-12-24 00:23:08.790476 | controller | ok 2025-12-24 00:23:08.813217 | 2025-12-24 00:23:08.813349 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-24 00:23:09.060781 | controller | /usr/bin/virtualenv 2025-12-24 00:23:09.381261 | controller | ok: Runtime: 0:00:00.005009 2025-12-24 00:23:09.394948 | 2025-12-24 00:23:09.395189 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-24 00:23:09.427926 | controller | skipping: Conditional result was False 2025-12-24 00:23:09.428278 | controller | ok: All items complete 2025-12-24 00:23:09.428308 | 2025-12-24 00:23:09.460239 | 2025-12-24 00:23:09.460644 | TASK [Find the full path of the Python interpreter] 2025-12-24 00:23:09.695123 | controller | /usr/bin/python3 2025-12-24 00:23:10.010298 | controller | ok 2025-12-24 00:23:10.023573 | 2025-12-24 00:23:10.023737 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-24 00:23:11.002549 | controller | created virtual environment CPython3.11.0.final.0-64 in 494ms 2025-12-24 00:23:11.031174 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-24 00:23:11.031775 | 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-24 00:23:11.032068 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-24 00:23:11.032388 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-24 00:23:11.082732 | controller | changed 2025-12-24 00:23:11.095200 | 2025-12-24 00:23:11.095397 | TASK [Set selinux package] 2025-12-24 00:23:11.137630 | controller | ok 2025-12-24 00:23:11.148844 | 2025-12-24 00:23:11.148974 | TASK [Set selinux package (Fedora)] 2025-12-24 00:23:11.203811 | controller | ok 2025-12-24 00:23:11.211007 | 2025-12-24 00:23:11.211108 | TASK [Install selinux into virtualenv] 2025-12-24 00:23:48.688761 | controller | Collecting selinux-please-lie-to-me 2025-12-24 00:24:00.931438 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-24 00:24:01.237564 | controller | Collecting setuptools<50.0.0 2025-12-24 00:24:01.245570 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-24 00:24:01.293853 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 18.6 MB/s eta 0:00:00 2025-12-24 00:24:01.377049 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-24 00:24:01.377135 | controller | Attempting uninstall: setuptools 2025-12-24 00:24:01.379520 | controller | Found existing installation: setuptools 62.6.0 2025-12-24 00:24:01.438821 | controller | Uninstalling setuptools-62.6.0: 2025-12-24 00:24:01.446660 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-24 00:24:01.784717 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-24 00:24:13.307435 | controller | 2025-12-24 00:24:13.389450 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-24 00:24:13.389494 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-24 00:24:13.790918 | controller | ok: Runtime: 0:01:01.956872 2025-12-24 00:24:13.804414 | 2025-12-24 00:24:13.804566 | TASK [Install pytest-forked into virtualenv] 2025-12-24 00:24:38.670297 | controller | Collecting pytest-forked 2025-12-24 00:24:50.917277 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-24 00:24:50.965548 | controller | Collecting py 2025-12-24 00:24:50.970406 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-24 00:24:50.988601 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 6.1 MB/s eta 0:00:00 2025-12-24 00:24:51.098197 | controller | Collecting pytest>=3.10 2025-12-24 00:24:51.104636 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-24 00:24:51.119812 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 32.7 MB/s eta 0:00:00 2025-12-24 00:24:51.156650 | controller | Collecting iniconfig>=1.0.1 2025-12-24 00:24:51.161335 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-24 00:24:51.204483 | controller | Collecting packaging>=22 2025-12-24 00:24:51.211449 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-24 00:24:51.217723 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 16.3 MB/s eta 0:00:00 2025-12-24 00:24:51.252127 | controller | Collecting pluggy<2,>=1.5 2025-12-24 00:24:51.255572 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-24 00:24:51.300084 | controller | Collecting pygments>=2.7.2 2025-12-24 00:24:51.305576 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-24 00:24:51.337851 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 44.0 MB/s eta 0:00:00 2025-12-24 00:24:51.408187 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-24 00:24:52.484536 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-9.0.2 pytest-forked-1.6.0 2025-12-24 00:24:52.493383 | controller | 2025-12-24 00:24:52.561649 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-24 00:24:52.561691 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-24 00:24:52.878770 | controller | ok: Runtime: 0:00:38.516528 2025-12-24 00:24:52.885292 | 2025-12-24 00:24:52.885357 | TASK [Update pip] 2025-12-24 00:24:53.425970 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-24 00:25:27.179984 | controller | Collecting pip 2025-12-24 00:25:51.464042 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-24 00:25:51.542947 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 24.0 MB/s eta 0:00:00 2025-12-24 00:25:51.606083 | controller | Installing collected packages: pip 2025-12-24 00:25:51.606236 | controller | Attempting uninstall: pip 2025-12-24 00:25:51.608327 | controller | Found existing installation: pip 22.2.2 2025-12-24 00:25:51.743948 | controller | Uninstalling pip-22.2.2: 2025-12-24 00:25:51.758689 | controller | Successfully uninstalled pip-22.2.2 2025-12-24 00:25:52.549285 | controller | Successfully installed pip-25.3 2025-12-24 00:25:52.957503 | controller | ok: Runtime: 0:00:59.487765 2025-12-24 00:25:52.971278 | 2025-12-24 00:25:52.971490 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-24 00:25:53.219072 | controller | changed 2025-12-24 00:25:53.232351 | 2025-12-24 00:25:53.232484 | TASK [Install ansible into virtualenv] 2025-12-24 00:25:53.761440 | controller | Processing ./src/github.com/ansible/ansible 2025-12-24 00:25:53.764830 | controller | Installing build dependencies: started 2025-12-24 00:26:16.470278 | controller | Installing build dependencies: finished with status 'done' 2025-12-24 00:26:16.470970 | controller | Getting requirements to build wheel: started 2025-12-24 00:26:17.231226 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-24 00:26:17.232115 | controller | Preparing metadata (pyproject.toml): started 2025-12-24 00:26:17.713721 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-24 00:26:17.719303 | 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-24 00:26:17.723018 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-24 00:26:17.819440 | controller | ERROR 2025-12-24 00:26:17.820131 | controller | { 2025-12-24 00:26:17.820170 | controller | "delta": "0:00:24.309659", 2025-12-24 00:26:17.820190 | controller | "end": "2025-12-24 00:26:17.789884", 2025-12-24 00:26:17.820207 | controller | "msg": "non-zero return code", 2025-12-24 00:26:17.820241 | controller | "rc": 1, 2025-12-24 00:26:17.820257 | controller | "start": "2025-12-24 00:25:53.480225" 2025-12-24 00:26:17.820273 | controller | } failure 2025-12-24 00:26:17.822156 | 2025-12-24 00:26:17.822221 | PLAY RECAP 2025-12-24 00:26:17.822279 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-24 00:26:17.822306 | 2025-12-24 00:26:18.041493 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-24 00:26:18.042527 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-24 00:26:18.734226 | 2025-12-24 00:26:18.734346 | PLAY [all] 2025-12-24 00:26:18.757422 | 2025-12-24 00:26:18.757584 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-24 00:26:19.004320 | controller | changed: non-zero return code 2025-12-24 00:26:19.010261 | 2025-12-24 00:26:19.010340 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-24 00:26:19.035114 | controller | skipping: Conditional result was False 2025-12-24 00:26:19.041418 | 2025-12-24 00:26:19.041490 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-24 00:26:19.082831 | 2025-12-24 00:26:19.082985 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-24 00:26:19.114165 | 2025-12-24 00:26:19.114330 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-24 00:26:19.138633 | controller | skipping: Conditional result was False 2025-12-24 00:26:19.146258 | 2025-12-24 00:26:19.146330 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-24 00:26:19.167493 | 2025-12-24 00:26:19.167623 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-24 00:26:19.191480 | controller | skipping: Conditional result was False 2025-12-24 00:26:19.198462 | 2025-12-24 00:26:19.198534 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-24 00:26:19.222936 | controller | skipping: Conditional result was False 2025-12-24 00:26:19.229447 | 2025-12-24 00:26:19.229521 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-24 00:26:19.253461 | controller | skipping: Conditional result was False 2025-12-24 00:26:19.280093 | 2025-12-24 00:26:19.280159 | PLAY RECAP 2025-12-24 00:26:19.280202 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-24 00:26:19.280222 | 2025-12-24 00:26:19.390914 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-24 00:26:19.392890 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-24 00:26:20.011423 | 2025-12-24 00:26:20.011534 | PLAY [all:!appliance*] 2025-12-24 00:26:20.033989 | 2025-12-24 00:26:20.034125 | TASK [unregister the node] 2025-12-24 00:26:20.564853 | controller | skipping: Conditional result was False 2025-12-24 00:26:20.577852 | 2025-12-24 00:26:20.578060 | TASK [include_role : fetch-output] 2025-12-24 00:26:20.617122 | controller | ok 2025-12-24 00:26:20.662598 | 2025-12-24 00:26:20.662696 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-24 00:26:20.729337 | controller | skipping: Conditional result was False 2025-12-24 00:26:20.742571 | 2025-12-24 00:26:20.742717 | TASK [fetch-output : Set log path for single node] 2025-12-24 00:26:20.799178 | controller | ok 2025-12-24 00:26:20.807168 | 2025-12-24 00:26:20.807257 | LOOP [fetch-output : Ensure local output dirs] 2025-12-24 00:26:21.334565 | controller -> localhost | ok: "/var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/work/logs" 2025-12-24 00:26:21.582211 | controller -> localhost | changed: "/var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/work/artifacts" 2025-12-24 00:26:21.784978 | controller -> localhost | changed: "/var/lib/zuul/builds/ef626e746d5c4bf3b8143fb8bc108548/work/docs" 2025-12-24 00:26:21.805489 | 2025-12-24 00:26:21.805660 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-24 00:26:22.574514 | controller | changed: 2025-12-24 00:26:22.574875 | controller | .d..t...... ./ 2025-12-24 00:26:22.575102 | controller | cd+++++++++ controller/ 2025-12-24 00:26:22.575188 | controller | changed: All items complete 2025-12-24 00:26:22.575233 | 2025-12-24 00:26:23.057079 | controller | changed: .d..t...... ./ 2025-12-24 00:26:23.655233 | controller | changed: .d..t...... ./ 2025-12-24 00:26:23.679620 | 2025-12-24 00:26:23.679759 | TASK [include_role : fetch-output-openshift] 2025-12-24 00:26:23.704964 | controller | skipping: Conditional result was False 2025-12-24 00:26:23.716227 | 2025-12-24 00:26:23.716366 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-24 00:26:23.760331 | controller | skipping: Conditional result was False 2025-12-24 00:26:23.773067 | controller | skipping: Conditional result was False 2025-12-24 00:26:23.825249 | 2025-12-24 00:26:23.825432 | PLAY [localhost] 2025-12-24 00:26:23.840413 | 2025-12-24 00:26:23.840490 | TASK [Run Zuul manifest role] 2025-12-24 00:26:23.871716 | localhost | ok 2025-12-24 00:26:23.887239 | 2025-12-24 00:26:23.887317 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-24 00:26:24.318343 | localhost | changed 2025-12-24 00:26:24.324262 | 2025-12-24 00:26:24.324352 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-24 00:26:24.355941 | localhost | ok 2025-12-24 00:26:24.364234 | 2025-12-24 00:26:24.364308 | TASK [Set zuul-log-path fact] 2025-12-24 00:26:24.382919 | localhost | ok 2025-12-24 00:26:24.398748 | 2025-12-24 00:26:24.398852 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-24 00:26:24.427869 | localhost | ok 2025-12-24 00:26:24.436481 | 2025-12-24 00:26:24.436541 | LOOP [Run upload-logs-swift role] 2025-12-24 00:26:24.460205 | localhost | Output suppressed because no_log was given 2025-12-24 00:26:24.489680 | 2025-12-24 00:26:24.489816 | TASK [Set zuul-log-path fact] 2025-12-24 00:26:24.525128 | localhost | skipping: Conditional result was False 2025-12-24 00:26:24.536509 | 2025-12-24 00:26:24.536639 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-24 00:26:24.982264 | localhost -> localhost | ok: Runtime: 0:00:00.010800 2025-12-24 00:26:24.994110 | 2025-12-24 00:26:24.994276 | TASK [upload-logs-swift : Upload logs to swift]