2025-10-06 00:12:02.116767 | Job console starting... 2025-10-06 00:12:02.126358 | Updating repositories 2025-10-06 00:12:02.257695 | Preparing job workspace 2025-10-06 00:12:06.792321 | Running Ansible setup... 2025-10-06 00:12:15.397685 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-06 00:12:16.047406 | 2025-10-06 00:12:16.047533 | PLAY [localhost] 2025-10-06 00:12:16.056522 | 2025-10-06 00:12:16.056604 | TASK [Gathering Facts] 2025-10-06 00:12:17.061697 | localhost | ok 2025-10-06 00:12:17.086343 | 2025-10-06 00:12:17.086454 | TASK [Setup log path fact] 2025-10-06 00:12:17.114631 | localhost | ok 2025-10-06 00:12:17.127682 | 2025-10-06 00:12:17.127779 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-06 00:12:17.155097 | localhost | ok 2025-10-06 00:12:17.162901 | 2025-10-06 00:12:17.162968 | TASK [emit-job-header : Print job information] 2025-10-06 00:12:17.190334 | # Job Information 2025-10-06 00:12:17.190482 | Ansible Version: 2.15.12 2025-10-06 00:12:17.190512 | Job: ansible-test-sanity-docker-milestone 2025-10-06 00:12:17.190533 | Pipeline: periodic 2025-10-06 00:12:17.190551 | Executor: ze03.softwarefactory-project.io 2025-10-06 00:12:17.190569 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-06 00:12:17.190597 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/e09/ansible/e09ea0010a834bf2985b852f631aca06/ 2025-10-06 00:12:17.190622 | Event ID: 9d310e2ddb83445ab53d82797698fe1c 2025-10-06 00:12:17.194416 | 2025-10-06 00:12:17.194476 | LOOP [emit-job-header : Print node information] 2025-10-06 00:12:17.290054 | localhost | ok: 2025-10-06 00:12:17.290230 | localhost | # Node Information 2025-10-06 00:12:17.290269 | localhost | Inventory Hostname: controller 2025-10-06 00:12:17.290296 | localhost | Hostname: np0005471459 2025-10-06 00:12:17.290322 | localhost | Username: zuul 2025-10-06 00:12:17.290350 | localhost | Distro: Fedora 37 2025-10-06 00:12:17.290375 | localhost | Provider: ansible-vexxhost-ams1 2025-10-06 00:12:17.290399 | localhost | Region: ams1 2025-10-06 00:12:17.290422 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-06 00:12:17.290445 | localhost | Product Name: OpenStack Nova 2025-10-06 00:12:17.290468 | localhost | Interface IP: 38.129.16.43 2025-10-06 00:12:17.299619 | 2025-10-06 00:12:17.299762 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-06 00:12:17.671258 | localhost -> localhost | changed 2025-10-06 00:12:17.677603 | 2025-10-06 00:12:17.677705 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-06 00:12:19.227047 | localhost -> localhost | changed 2025-10-06 00:12:19.246953 | 2025-10-06 00:12:19.247089 | PLAY [all:!appliance*] 2025-10-06 00:12:19.263914 | 2025-10-06 00:12:19.263986 | TASK [include_role : start-zuul-console] 2025-10-06 00:12:19.301321 | controller | ok 2025-10-06 00:12:19.317595 | 2025-10-06 00:12:19.317718 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-06 00:12:20.564563 | controller | ok 2025-10-06 00:12:20.582848 | 2025-10-06 00:12:20.582957 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-06 00:12:22.934081 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-06 00:12:22.953523 | 2025-10-06 00:12:22.953621 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-06 00:12:23.313938 | controller | skipping: Conditional result was False 2025-10-06 00:12:23.320646 | 2025-10-06 00:12:23.320739 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-06 00:12:23.345082 | controller | skipping: Conditional result was False 2025-10-06 00:12:23.351478 | 2025-10-06 00:12:23.351553 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-06 00:12:23.375884 | controller | skipping: Conditional result was False 2025-10-06 00:12:23.383503 | 2025-10-06 00:12:23.383594 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-06 00:12:23.409006 | controller | skipping: Conditional result was False 2025-10-06 00:12:23.420450 | 2025-10-06 00:12:23.420540 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-06 00:12:23.450611 | controller | skipping: Conditional result was False 2025-10-06 00:12:23.457480 | 2025-10-06 00:12:23.457561 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-06 00:12:23.475375 | controller | skipping: Conditional result was False 2025-10-06 00:12:23.488541 | 2025-10-06 00:12:23.488650 | TASK [Disable Fedora Modular] 2025-10-06 00:12:24.759576 | controller | changed 2025-10-06 00:12:24.775151 | 2025-10-06 00:12:24.775326 | TASK [Enable EPEL] 2025-10-06 00:12:24.822895 | controller | skipping: Conditional result was False 2025-10-06 00:12:24.829614 | 2025-10-06 00:12:24.829721 | TASK [Register the RHEL node] 2025-10-06 00:12:25.232457 | 2025-10-06 00:12:25.232662 | TASK [Show the subscription-manager status] 2025-10-06 00:12:25.623956 | controller | skipping: Conditional result was False 2025-10-06 00:12:25.638698 | 2025-10-06 00:12:25.638894 | TASK [Enable EPEL on RHEL] 2025-10-06 00:12:26.076393 | controller | skipping: Conditional result was False 2025-10-06 00:12:26.089615 | 2025-10-06 00:12:26.089822 | TASK [Install git and tox] 2025-10-06 00:15:15.918373 | controller | changed 2025-10-06 00:15:15.933083 | 2025-10-06 00:15:15.933246 | TASK [include_role : prepare-workspace] 2025-10-06 00:15:15.974682 | controller | ok 2025-10-06 00:15:16.013075 | 2025-10-06 00:15:16.013755 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-06 00:15:16.897073 | controller | ok 2025-10-06 00:15:16.903699 | 2025-10-06 00:15:16.903793 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-06 00:15:33.189507 | controller | Output suppressed because no_log was given 2025-10-06 00:15:33.200356 | 2025-10-06 00:15:33.200454 | TASK [include_role : prepare-workspace-openshift] 2025-10-06 00:15:33.224515 | controller | skipping: Conditional result was False 2025-10-06 00:15:33.246339 | 2025-10-06 00:15:33.246421 | PLAY [all:!appliance] 2025-10-06 00:15:33.263461 | 2025-10-06 00:15:33.263570 | TASK [Run add-build-sshkey role (RSA)] 2025-10-06 00:15:33.295997 | controller | ok 2025-10-06 00:15:33.320169 | 2025-10-06 00:15:33.320322 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-06 00:15:33.580947 | controller -> localhost | ok 2025-10-06 00:15:33.596383 | 2025-10-06 00:15:33.596571 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-06 00:15:33.619742 | controller | ok 2025-10-06 00:15:33.633766 | controller | included: /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-06 00:15:33.639763 | 2025-10-06 00:15:33.639841 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-06 00:15:34.110274 | controller -> localhost | Generating public/private rsa key pair. 2025-10-06 00:15:34.110470 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/work/e09ea0010a834bf2985b852f631aca06_id_rsa. 2025-10-06 00:15:34.110499 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/work/e09ea0010a834bf2985b852f631aca06_id_rsa.pub. 2025-10-06 00:15:34.110519 | controller -> localhost | The key fingerprint is: 2025-10-06 00:15:34.110538 | controller -> localhost | SHA256:aY7awE/K0Uk/yjRexBDCDqUXdbHVfR++DqzC+0a91xg zuul-build-sshkey 2025-10-06 00:15:34.110557 | controller -> localhost | The key's randomart image is: 2025-10-06 00:15:34.110575 | controller -> localhost | +---[RSA 2048]----+ 2025-10-06 00:15:34.110592 | controller -> localhost | | o+.o o... . | 2025-10-06 00:15:34.110611 | controller -> localhost | | ...o o o . ...| 2025-10-06 00:15:34.110628 | controller -> localhost | | .o. . . ..o| 2025-10-06 00:15:34.110645 | controller -> localhost | | .. o . ..| 2025-10-06 00:15:34.110662 | controller -> localhost | | . S o .| 2025-10-06 00:15:34.110688 | controller -> localhost | | . o B . +E. | 2025-10-06 00:15:34.110712 | controller -> localhost | | + B * . . +o.| 2025-10-06 00:15:34.110749 | controller -> localhost | | . % + + o ..o.| 2025-10-06 00:15:34.110769 | controller -> localhost | | + * .=. . | 2025-10-06 00:15:34.110789 | controller -> localhost | +----[SHA256]-----+ 2025-10-06 00:15:34.110835 | controller -> localhost | ok: Runtime: 0:00:00.081327 2025-10-06 00:15:34.117266 | 2025-10-06 00:15:34.117332 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-06 00:15:34.147804 | controller | ok 2025-10-06 00:15:34.158041 | controller | included: /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-06 00:15:34.167274 | 2025-10-06 00:15:34.167371 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-06 00:15:34.192202 | controller | skipping: Conditional result was False 2025-10-06 00:15:34.200009 | 2025-10-06 00:15:34.200161 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-06 00:15:35.410040 | controller | changed 2025-10-06 00:15:35.424871 | 2025-10-06 00:15:35.425070 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-06 00:15:36.151419 | controller | ok 2025-10-06 00:15:36.165498 | 2025-10-06 00:15:36.165684 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-06 00:15:39.486221 | controller | changed 2025-10-06 00:15:39.494987 | 2025-10-06 00:15:39.495123 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-06 00:15:42.616618 | controller | changed 2025-10-06 00:15:42.630151 | 2025-10-06 00:15:42.630304 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-06 00:15:42.657572 | controller | skipping: Conditional result was False 2025-10-06 00:15:42.673536 | 2025-10-06 00:15:42.673710 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-06 00:15:43.129329 | controller -> localhost | changed 2025-10-06 00:15:43.156149 | 2025-10-06 00:15:43.156326 | TASK [add-build-sshkey : Add back temp key] 2025-10-06 00:15:43.531072 | controller -> localhost | Identity added: /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/work/e09ea0010a834bf2985b852f631aca06_id_rsa (zuul-build-sshkey) 2025-10-06 00:15:43.531279 | controller -> localhost | ok: Runtime: 0:00:00.007713 2025-10-06 00:15:43.539186 | 2025-10-06 00:15:43.539250 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-06 00:15:44.512761 | controller | ok 2025-10-06 00:15:44.526055 | 2025-10-06 00:15:44.526278 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-06 00:15:44.566105 | controller | skipping: Conditional result was False 2025-10-06 00:15:44.593171 | 2025-10-06 00:15:44.593380 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-06 00:15:44.626989 | controller | ok 2025-10-06 00:15:44.654691 | 2025-10-06 00:15:44.654889 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-06 00:15:44.937403 | controller -> localhost | ok 2025-10-06 00:15:44.948236 | 2025-10-06 00:15:44.948405 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-06 00:15:44.978676 | controller | ok 2025-10-06 00:15:44.999785 | controller | included: /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-06 00:15:45.009486 | 2025-10-06 00:15:45.009581 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-06 00:15:45.350434 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-06 00:15:45.350834 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/work/e09ea0010a834bf2985b852f631aca06_id_ecdsa. 2025-10-06 00:15:45.350927 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/work/e09ea0010a834bf2985b852f631aca06_id_ecdsa.pub. 2025-10-06 00:15:45.350988 | controller -> localhost | The key fingerprint is: 2025-10-06 00:15:45.351031 | controller -> localhost | SHA256:V0P3/bZre3QN8FefHKyV0o2MBImDmNU/i2suuPuWT8A zuul-build-sshkey 2025-10-06 00:15:45.351074 | controller -> localhost | The key's randomart image is: 2025-10-06 00:15:45.351115 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-06 00:15:45.351153 | controller -> localhost | | +.o ..+oo+.o| 2025-10-06 00:15:45.351191 | controller -> localhost | | o . + ..oooB+| 2025-10-06 00:15:45.351230 | controller -> localhost | | o oo= B| 2025-10-06 00:15:45.351268 | controller -> localhost | | . o. ooo+| 2025-10-06 00:15:45.351305 | controller -> localhost | | E S..o o+| 2025-10-06 00:15:45.351342 | controller -> localhost | | .... .=| 2025-10-06 00:15:45.351380 | controller -> localhost | | . ... o.| 2025-10-06 00:15:45.351417 | controller -> localhost | | . +.o .o| 2025-10-06 00:15:45.351453 | controller -> localhost | | o=.=o .oo| 2025-10-06 00:15:45.351491 | controller -> localhost | +----[SHA256]-----+ 2025-10-06 00:15:45.351586 | controller -> localhost | ok: Runtime: 0:00:00.016850 2025-10-06 00:15:45.411423 | 2025-10-06 00:15:45.411579 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-06 00:15:45.444407 | controller | ok 2025-10-06 00:15:45.455843 | controller | included: /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-06 00:15:45.469266 | 2025-10-06 00:15:45.469402 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-06 00:15:45.495087 | controller | skipping: Conditional result was False 2025-10-06 00:15:45.505153 | 2025-10-06 00:15:45.505299 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-06 00:15:46.554711 | controller | changed 2025-10-06 00:15:46.564329 | 2025-10-06 00:15:46.564440 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-06 00:15:47.276991 | controller | ok 2025-10-06 00:15:47.289781 | 2025-10-06 00:15:47.289966 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-06 00:15:50.415085 | controller | changed 2025-10-06 00:15:50.428438 | 2025-10-06 00:15:50.428583 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-06 00:15:53.603307 | controller | changed 2025-10-06 00:15:53.610863 | 2025-10-06 00:15:53.611057 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-06 00:15:53.649212 | controller | skipping: Conditional result was False 2025-10-06 00:15:53.664267 | 2025-10-06 00:15:53.664465 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-06 00:15:53.969089 | controller -> localhost | changed 2025-10-06 00:15:53.980988 | 2025-10-06 00:15:53.981099 | TASK [add-build-sshkey : Add back temp key] 2025-10-06 00:15:54.302012 | controller -> localhost | Identity added: /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/work/e09ea0010a834bf2985b852f631aca06_id_ecdsa (zuul-build-sshkey) 2025-10-06 00:15:54.302210 | controller -> localhost | ok: Runtime: 0:00:00.015494 2025-10-06 00:15:54.309323 | 2025-10-06 00:15:54.309431 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-06 00:15:55.055790 | controller | ok 2025-10-06 00:15:55.063375 | 2025-10-06 00:15:55.063546 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-06 00:15:55.089465 | controller | skipping: Conditional result was False 2025-10-06 00:15:55.114694 | 2025-10-06 00:15:55.114832 | TASK [include_role : remove-zuul-sshkey] 2025-10-06 00:15:55.139964 | controller | skipping: Conditional result was False 2025-10-06 00:15:55.156172 | 2025-10-06 00:15:55.156365 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-06 00:15:55.929183 | controller | ok: "logs" 2025-10-06 00:15:55.929452 | controller | ok: All items complete 2025-10-06 00:15:55.929488 | 2025-10-06 00:15:56.635590 | controller | ok: "artifacts" 2025-10-06 00:15:57.371798 | controller | ok: "docs" 2025-10-06 00:15:57.391266 | 2025-10-06 00:15:57.391419 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-06 00:15:58.119698 | controller | changed: "logs" 2025-10-06 00:15:58.863429 | controller | changed: "artifacts" 2025-10-06 00:15:59.603577 | controller | changed: "docs" 2025-10-06 00:15:59.657902 | 2025-10-06 00:15:59.658014 | PLAY RECAP 2025-10-06 00:15:59.658075 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-06 00:15:59.658112 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-06 00:15:59.658171 | 2025-10-06 00:15:59.775021 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-06 00:15:59.776613 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-06 00:16:00.353926 | 2025-10-06 00:16:00.354094 | PLAY [all] 2025-10-06 00:16:00.383442 | 2025-10-06 00:16:00.383616 | TASK [Install binary dependencies] 2025-10-06 00:16:00.445469 | controller | ok 2025-10-06 00:16:00.465310 | 2025-10-06 00:16:00.465459 | TASK [bindep : Include find tasks] 2025-10-06 00:16:00.498537 | controller | ok 2025-10-06 00:16:00.510534 | controller | included: /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-06 00:16:00.520062 | 2025-10-06 00:16:00.520159 | TASK [bindep : Look for bindep.txt] 2025-10-06 00:16:01.590242 | controller | ok 2025-10-06 00:16:01.599713 | 2025-10-06 00:16:01.599880 | TASK [bindep : Define bindep_file fact] 2025-10-06 00:16:01.626287 | controller | skipping: Conditional result was False 2025-10-06 00:16:01.635964 | 2025-10-06 00:16:01.636128 | TASK [bindep : Look for other-requirements.txt] 2025-10-06 00:16:02.320648 | controller | ok 2025-10-06 00:16:02.326616 | 2025-10-06 00:16:02.326684 | TASK [bindep : Define bindep_file fact] 2025-10-06 00:16:02.340922 | controller | skipping: Conditional result was False 2025-10-06 00:16:02.347190 | 2025-10-06 00:16:02.347262 | TASK [bindep : Look for bindep fallback file] 2025-10-06 00:16:02.381166 | controller | skipping: Conditional result was False 2025-10-06 00:16:02.392150 | 2025-10-06 00:16:02.392300 | TASK [bindep : Define bindep_file fact] 2025-10-06 00:16:02.418718 | controller | skipping: Conditional result was False 2025-10-06 00:16:02.429654 | 2025-10-06 00:16:02.429846 | TASK [bindep : Include bindep tasks] 2025-10-06 00:16:02.455693 | controller | skipping: Conditional result was False 2025-10-06 00:16:02.471231 | 2025-10-06 00:16:02.471439 | TASK [bindep : Include install tasks] 2025-10-06 00:16:02.508491 | controller | skipping: Conditional result was False 2025-10-06 00:16:02.524633 | 2025-10-06 00:16:02.524946 | LOOP [bindep : Include package tasks] 2025-10-06 00:16:02.607192 | 2025-10-06 00:16:02.607362 | TASK [Run test-setup role] 2025-10-06 00:16:02.626605 | controller | ok 2025-10-06 00:16:02.648134 | 2025-10-06 00:16:02.648234 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-06 00:16:03.306393 | controller | ok 2025-10-06 00:16:03.314858 | 2025-10-06 00:16:03.315015 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-06 00:16:03.676004 | controller | skipping: Conditional result was False 2025-10-06 00:16:03.703218 | 2025-10-06 00:16:03.703314 | PLAY RECAP 2025-10-06 00:16:03.703353 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-06 00:16:03.703373 | 2025-10-06 00:16:03.829135 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-06 00:16:03.830014 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-06 00:16:04.505462 | 2025-10-06 00:16:04.505606 | PLAY [controller] 2025-10-06 00:16:04.532655 | 2025-10-06 00:16:04.532873 | TASK [Create the /root directory] 2025-10-06 00:16:05.643063 | controller | ok 2025-10-06 00:16:05.659617 | 2025-10-06 00:16:05.659765 | TASK [Install glibc-langpack-en] 2025-10-06 00:16:14.527817 | controller | ok: Nothing to do 2025-10-06 00:16:14.542797 | 2025-10-06 00:16:14.542949 | TASK [Ensure controller directory exists] 2025-10-06 00:16:15.456978 | controller | changed 2025-10-06 00:16:15.470293 | 2025-10-06 00:16:15.470482 | TASK [Install container runtime] 2025-10-06 00:16:15.530282 | controller | ok 2025-10-06 00:16:15.591072 | 2025-10-06 00:16:15.591307 | LOOP [ensure-podman : Find distribution installation] 2025-10-06 00:16:15.629586 | controller | ok: "/var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-06 00:16:15.657269 | controller | included: /var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-06 00:16:15.672664 | 2025-10-06 00:16:15.672895 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-06 00:18:43.043261 | controller | changed 2025-10-06 00:18:43.058406 | 2025-10-06 00:18:43.058559 | TASK [ensure-podman : Fetch podman version] 2025-10-06 00:18:44.279776 | controller | Client: Podman Engine 2025-10-06 00:18:44.324673 | controller | Version: 4.6.2 2025-10-06 00:18:44.324731 | controller | API Version: 4.6.2 2025-10-06 00:18:44.324739 | controller | Go Version: go1.19.12 2025-10-06 00:18:44.324760 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-06 00:18:44.324768 | controller | OS/Arch: linux/amd64 2025-10-06 00:18:44.933811 | controller | ok: Runtime: 0:00:00.304490 2025-10-06 00:18:44.947336 | 2025-10-06 00:18:44.947493 | TASK [ensure-podman : Print podman version installed] 2025-10-06 00:18:44.986049 | Podman version: Client: Podman Engine 2025-10-06 00:18:44.986298 | Version: 4.6.2 2025-10-06 00:18:44.986361 | API Version: 4.6.2 2025-10-06 00:18:44.986408 | Go Version: go1.19.12 2025-10-06 00:18:44.986448 | Built: Mon Aug 28 19:38:31 2023 2025-10-06 00:18:44.986490 | OS/Arch: linux/amd64 2025-10-06 00:18:44.999008 | 2025-10-06 00:18:44.999145 | TASK [ensure-podman : Validate podman engine] 2025-10-06 00:18:45.375796 | controller | skipping: Conditional result was False 2025-10-06 00:18:45.392479 | 2025-10-06 00:18:45.392778 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-06 00:18:45.420319 | controller | skipping: Conditional result was False 2025-10-06 00:18:45.449885 | 2025-10-06 00:18:45.450082 | TASK [Ensure python3.8 is present] 2025-10-06 00:18:45.477372 | controller | skipping: Conditional result was False 2025-10-06 00:18:45.487931 | 2025-10-06 00:18:45.488045 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-06 00:18:45.516949 | controller | ok 2025-10-06 00:18:45.547754 | 2025-10-06 00:18:45.547898 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-06 00:18:49.422479 | controller | ok: Nothing to do 2025-10-06 00:18:49.428249 | 2025-10-06 00:18:49.428339 | TASK [our-ensure-python : Also install python3-devel] 2025-10-06 00:19:05.819333 | controller | changed 2025-10-06 00:19:05.848419 | 2025-10-06 00:19:05.848566 | TASK [Run ensure-virtualenv role] 2025-10-06 00:19:05.872159 | controller | ok 2025-10-06 00:19:05.928344 | 2025-10-06 00:19:05.928458 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-06 00:19:06.697091 | controller | /usr/bin/virtualenv 2025-10-06 00:19:07.285797 | controller | ok: Runtime: 0:00:00.004826 2025-10-06 00:19:07.299258 | 2025-10-06 00:19:07.299451 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-06 00:19:07.323396 | controller | skipping: Conditional result was False 2025-10-06 00:19:07.323648 | controller | ok: All items complete 2025-10-06 00:19:07.323675 | 2025-10-06 00:19:07.351221 | 2025-10-06 00:19:07.351414 | TASK [Find the full path of the Python interpreter] 2025-10-06 00:19:08.227138 | controller | /usr/bin/python3 2025-10-06 00:19:08.730211 | controller | ok 2025-10-06 00:19:08.744307 | 2025-10-06 00:19:08.744470 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-06 00:19:10.763574 | controller | created virtual environment CPython3.11.0.final.0-64 in 1011ms 2025-10-06 00:19:10.816731 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-06 00:19:10.816786 | 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-10-06 00:19:10.816801 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-06 00:19:10.816821 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-06 00:19:11.129941 | controller | changed 2025-10-06 00:19:11.145075 | 2025-10-06 00:19:11.145268 | TASK [Set selinux package] 2025-10-06 00:19:11.177944 | controller | ok 2025-10-06 00:19:11.198617 | 2025-10-06 00:19:11.198835 | TASK [Set selinux package (Fedora)] 2025-10-06 00:19:11.255857 | controller | ok 2025-10-06 00:19:11.266356 | 2025-10-06 00:19:11.266491 | TASK [Install selinux into virtualenv] 2025-10-06 00:19:14.591504 | controller | Collecting selinux-please-lie-to-me 2025-10-06 00:19:14.671211 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-06 00:19:15.305504 | controller | Collecting setuptools<50.0.0 2025-10-06 00:19:15.311352 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-06 00:19:15.370699 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 15.8 MB/s eta 0:00:00 2025-10-06 00:19:15.527383 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-06 00:19:15.531753 | controller | Attempting uninstall: setuptools 2025-10-06 00:19:15.533426 | controller | Found existing installation: setuptools 62.6.0 2025-10-06 00:19:15.656093 | controller | Uninstalling setuptools-62.6.0: 2025-10-06 00:19:15.670775 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-06 00:19:16.569660 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-06 00:19:16.786957 | controller | 2025-10-06 00:19:17.321655 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-06 00:19:17.322397 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-06 00:19:17.669888 | controller | ok: Runtime: 0:00:05.251479 2025-10-06 00:19:17.676067 | 2025-10-06 00:19:17.676136 | TASK [Install pytest-forked into virtualenv] 2025-10-06 00:19:19.340925 | controller | Collecting pytest-forked 2025-10-06 00:19:19.419023 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-06 00:19:19.513704 | controller | Collecting py 2025-10-06 00:19:19.520614 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-06 00:19:19.570704 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.1 MB/s eta 0:00:00 2025-10-06 00:19:19.824830 | controller | Collecting pytest>=3.10 2025-10-06 00:19:19.833305 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-06 00:19:19.863430 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 19.3 MB/s eta 0:00:00 2025-10-06 00:19:19.947987 | controller | Collecting iniconfig>=1 2025-10-06 00:19:19.959362 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-06 00:19:20.047579 | controller | Collecting packaging>=20 2025-10-06 00:19:20.055833 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-06 00:19:20.069521 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.5 MB/s eta 0:00:00 2025-10-06 00:19:20.142064 | controller | Collecting pluggy<2,>=1.5 2025-10-06 00:19:20.150545 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-06 00:19:20.252799 | controller | Collecting pygments>=2.7.2 2025-10-06 00:19:20.258304 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-06 00:19:20.295561 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 37.4 MB/s eta 0:00:00 2025-10-06 00:19:20.445779 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-06 00:19:23.023837 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0 2025-10-06 00:19:23.041337 | controller | 2025-10-06 00:19:23.304068 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-06 00:19:23.304125 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-06 00:19:23.572623 | controller | ok: Runtime: 0:00:04.828243 2025-10-06 00:19:23.578795 | 2025-10-06 00:19:23.578862 | TASK [Update pip] 2025-10-06 00:19:25.132501 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-06 00:19:25.453276 | controller | Collecting pip 2025-10-06 00:19:25.541598 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-06 00:19:25.658074 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 16.5 MB/s eta 0:00:00 2025-10-06 00:19:25.802058 | controller | Installing collected packages: pip 2025-10-06 00:19:25.802406 | controller | Attempting uninstall: pip 2025-10-06 00:19:25.806840 | controller | Found existing installation: pip 22.2.2 2025-10-06 00:19:26.115855 | controller | Uninstalling pip-22.2.2: 2025-10-06 00:19:26.151485 | controller | Successfully uninstalled pip-22.2.2 2025-10-06 00:19:28.264754 | controller | Successfully installed pip-25.2 2025-10-06 00:19:28.973491 | controller | ok: Runtime: 0:00:04.071332 2025-10-06 00:19:28.981120 | 2025-10-06 00:19:28.981206 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-06 00:19:29.942150 | controller | changed 2025-10-06 00:19:29.948073 | 2025-10-06 00:19:29.948147 | TASK [Install ansible into virtualenv] 2025-10-06 00:19:31.501091 | controller | Processing ./src/github.com/ansible/ansible 2025-10-06 00:19:31.511754 | controller | Installing build dependencies: started 2025-10-06 00:19:33.892285 | controller | Installing build dependencies: finished with status 'done' 2025-10-06 00:19:35.744839 | controller | Getting requirements to build wheel: started 2025-10-06 00:19:35.744906 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-06 00:19:35.746438 | controller | Preparing metadata (pyproject.toml): started 2025-10-06 00:19:36.690942 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-06 00:19:36.695219 | 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-10-06 00:19:36.701837 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-06 00:19:37.335963 | controller | ERROR 2025-10-06 00:19:37.336148 | controller | { 2025-10-06 00:19:37.336179 | controller | "delta": "0:00:06.207904", 2025-10-06 00:19:37.336199 | controller | "end": "2025-10-06 00:19:36.903066", 2025-10-06 00:19:37.336216 | controller | "msg": "non-zero return code", 2025-10-06 00:19:37.336246 | controller | "rc": 1, 2025-10-06 00:19:37.336264 | controller | "start": "2025-10-06 00:19:30.695162" 2025-10-06 00:19:37.336280 | controller | } failure 2025-10-06 00:19:37.337956 | 2025-10-06 00:19:37.338006 | PLAY RECAP 2025-10-06 00:19:37.338051 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-06 00:19:37.338072 | 2025-10-06 00:19:37.442600 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-06 00:19:37.443633 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-06 00:19:38.080235 | 2025-10-06 00:19:38.080360 | PLAY [all] 2025-10-06 00:19:38.101954 | 2025-10-06 00:19:38.102060 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-06 00:19:40.027063 | controller | changed: non-zero return code 2025-10-06 00:19:40.036425 | 2025-10-06 00:19:40.036546 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-06 00:19:40.063314 | controller | skipping: Conditional result was False 2025-10-06 00:19:40.072283 | 2025-10-06 00:19:40.072422 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-06 00:19:40.110893 | 2025-10-06 00:19:40.111273 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-06 00:19:40.146785 | 2025-10-06 00:19:40.147010 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-06 00:19:40.175458 | controller | skipping: Conditional result was False 2025-10-06 00:19:40.185344 | 2025-10-06 00:19:40.185493 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-06 00:19:40.224345 | 2025-10-06 00:19:40.224602 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-06 00:19:40.250370 | controller | skipping: Conditional result was False 2025-10-06 00:19:40.264087 | 2025-10-06 00:19:40.264257 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-06 00:19:40.289131 | controller | skipping: Conditional result was False 2025-10-06 00:19:40.296552 | 2025-10-06 00:19:40.296675 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-06 00:19:40.321124 | controller | skipping: Conditional result was False 2025-10-06 00:19:40.352429 | 2025-10-06 00:19:40.352555 | PLAY RECAP 2025-10-06 00:19:40.352601 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-06 00:19:40.352622 | 2025-10-06 00:19:40.488924 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-06 00:19:40.492597 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-06 00:19:41.210077 | 2025-10-06 00:19:41.210308 | PLAY [all:!appliance*] 2025-10-06 00:19:41.236058 | 2025-10-06 00:19:41.236272 | TASK [unregister the node] 2025-10-06 00:19:41.594030 | controller | skipping: Conditional result was False 2025-10-06 00:19:41.602877 | 2025-10-06 00:19:41.603092 | TASK [include_role : fetch-output] 2025-10-06 00:19:41.656756 | controller | ok 2025-10-06 00:19:41.677378 | 2025-10-06 00:19:41.677496 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-06 00:19:41.763056 | controller | skipping: Conditional result was False 2025-10-06 00:19:41.769469 | 2025-10-06 00:19:41.769618 | TASK [fetch-output : Set log path for single node] 2025-10-06 00:19:41.809855 | controller | ok 2025-10-06 00:19:41.815573 | 2025-10-06 00:19:41.815675 | LOOP [fetch-output : Ensure local output dirs] 2025-10-06 00:19:42.224616 | controller -> localhost | ok: "/var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/work/logs" 2025-10-06 00:19:42.483989 | controller -> localhost | changed: "/var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/work/artifacts" 2025-10-06 00:19:42.711220 | controller -> localhost | changed: "/var/lib/zuul/builds/e09ea0010a834bf2985b852f631aca06/work/docs" 2025-10-06 00:19:42.725299 | 2025-10-06 00:19:42.725428 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-06 00:19:45.025478 | controller | changed: 2025-10-06 00:19:45.025800 | controller | .d..t...... ./ 2025-10-06 00:19:45.025845 | controller | cd+++++++++ controller/ 2025-10-06 00:19:45.025890 | controller | changed: All items complete 2025-10-06 00:19:45.025919 | 2025-10-06 00:19:47.165374 | controller | changed: .d..t...... ./ 2025-10-06 00:19:49.294961 | controller | changed: .d..t...... ./ 2025-10-06 00:19:49.327952 | 2025-10-06 00:19:49.328131 | TASK [include_role : fetch-output-openshift] 2025-10-06 00:19:49.400612 | controller | skipping: Conditional result was False 2025-10-06 00:19:49.407837 | 2025-10-06 00:19:49.407955 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-06 00:19:49.465234 | controller | skipping: Conditional result was False 2025-10-06 00:19:49.465973 | controller | skipping: Conditional result was False 2025-10-06 00:19:49.533514 | 2025-10-06 00:19:49.533624 | PLAY [localhost] 2025-10-06 00:19:49.559040 | 2025-10-06 00:19:49.559161 | TASK [Run Zuul manifest role] 2025-10-06 00:19:49.579682 | localhost | ok 2025-10-06 00:19:49.597524 | 2025-10-06 00:19:49.597647 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-06 00:19:50.001301 | localhost | changed 2025-10-06 00:19:50.006130 | 2025-10-06 00:19:50.006195 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-06 00:19:50.067641 | localhost | ok 2025-10-06 00:19:50.080322 | 2025-10-06 00:19:50.080456 | TASK [Set zuul-log-path fact] 2025-10-06 00:19:50.131208 | localhost | ok 2025-10-06 00:19:50.144178 | 2025-10-06 00:19:50.144285 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-06 00:19:50.172892 | localhost | ok 2025-10-06 00:19:50.180995 | 2025-10-06 00:19:50.181106 | LOOP [Run upload-logs-swift role] 2025-10-06 00:19:50.234106 | localhost | Output suppressed because no_log was given 2025-10-06 00:19:50.266307 | 2025-10-06 00:19:50.266431 | TASK [Set zuul-log-path fact] 2025-10-06 00:19:50.291135 | localhost | skipping: Conditional result was False 2025-10-06 00:19:50.296339 | 2025-10-06 00:19:50.296477 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-06 00:19:50.691407 | localhost -> localhost | ok: Runtime: 0:00:00.016803 2025-10-06 00:19:50.696945 | 2025-10-06 00:19:50.697050 | TASK [upload-logs-swift : Upload logs to swift]