2025-11-06 00:06:39.660469 | Job console starting... 2025-11-06 00:06:39.670824 | Updating repositories 2025-11-06 00:06:42.471301 | Preparing job workspace 2025-11-06 00:06:46.470003 | Running Ansible setup... 2025-11-06 00:06:52.612195 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-06 00:06:53.298068 | 2025-11-06 00:06:53.298225 | PLAY [localhost] 2025-11-06 00:06:53.310085 | 2025-11-06 00:06:53.310243 | TASK [Gathering Facts] 2025-11-06 00:06:54.377067 | localhost | ok 2025-11-06 00:06:54.390606 | 2025-11-06 00:06:54.390812 | TASK [Setup log path fact] 2025-11-06 00:06:54.408677 | localhost | ok 2025-11-06 00:06:54.422283 | 2025-11-06 00:06:54.422411 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-06 00:06:54.450403 | localhost | ok 2025-11-06 00:06:54.459136 | 2025-11-06 00:06:54.459301 | TASK [emit-job-header : Print job information] 2025-11-06 00:06:54.508009 | # Job Information 2025-11-06 00:06:54.508173 | Ansible Version: 2.15.12 2025-11-06 00:06:54.508206 | Job: ansible-test-sanity-docker-devel 2025-11-06 00:06:54.508227 | Pipeline: periodic 2025-11-06 00:06:54.508246 | Executor: ze03.softwarefactory-project.io 2025-11-06 00:06:54.508268 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-11-06 00:06:54.508289 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/9fd/ansible/9fd2c594845b4b98afbb28f82942d3b5/ 2025-11-06 00:06:54.508307 | Event ID: 06b8e19d0def49e3b59e004861f83875 2025-11-06 00:06:54.512417 | 2025-11-06 00:06:54.512504 | LOOP [emit-job-header : Print node information] 2025-11-06 00:06:54.613229 | localhost | ok: 2025-11-06 00:06:54.613391 | localhost | # Node Information 2025-11-06 00:06:54.613418 | localhost | Inventory Hostname: controller 2025-11-06 00:06:54.613438 | localhost | Hostname: ip-172-16-151-142 2025-11-06 00:06:54.613456 | localhost | Username: zuul-worker 2025-11-06 00:06:54.613476 | localhost | Distro: Fedora 37 2025-11-06 00:06:54.613493 | localhost | Provider: ansible-us-east-2 2025-11-06 00:06:54.613509 | localhost | Region: us-east-2 2025-11-06 00:06:54.613526 | localhost | Label: ansible-fedora-37-1vcpu 2025-11-06 00:06:54.613541 | localhost | Product Name: t3.small 2025-11-06 00:06:54.613557 | localhost | Interface IP: 18.224.8.156 2025-11-06 00:06:54.626970 | 2025-11-06 00:06:54.627099 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-11-06 00:06:55.045635 | localhost -> localhost | changed 2025-11-06 00:06:55.051927 | 2025-11-06 00:06:55.052027 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-11-06 00:06:55.961230 | localhost -> localhost | changed 2025-11-06 00:06:55.982665 | 2025-11-06 00:06:55.982766 | PLAY [all:!appliance*] 2025-11-06 00:06:56.002398 | 2025-11-06 00:06:56.002543 | TASK [include_role : start-zuul-console] 2025-11-06 00:06:56.022165 | controller | ok 2025-11-06 00:06:56.036384 | 2025-11-06 00:06:56.036508 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-11-06 00:06:56.752213 | controller | ok 2025-11-06 00:06:56.791428 | 2025-11-06 00:06:56.791581 | TASK [use-our-mirror : Retrieve the IP address] 2025-11-06 00:06:59.133473 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-11-06 00:06:59.150694 | 2025-11-06 00:06:59.150936 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-11-06 00:06:59.315396 | controller | skipping: Conditional result was False 2025-11-06 00:06:59.324930 | 2025-11-06 00:06:59.325081 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-11-06 00:06:59.350498 | controller | skipping: Conditional result was False 2025-11-06 00:06:59.360458 | 2025-11-06 00:06:59.360625 | TASK [use-our-mirror : Create the podman configuration directory] 2025-11-06 00:06:59.386043 | controller | skipping: Conditional result was False 2025-11-06 00:06:59.395656 | 2025-11-06 00:06:59.395860 | TASK [use-our-mirror : Copy the podman configuration] 2025-11-06 00:06:59.421044 | controller | skipping: Conditional result was False 2025-11-06 00:06:59.429974 | 2025-11-06 00:06:59.430120 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-11-06 00:06:59.465705 | controller | skipping: Conditional result was False 2025-11-06 00:06:59.476175 | 2025-11-06 00:06:59.476334 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-11-06 00:06:59.503717 | controller | skipping: Conditional result was False 2025-11-06 00:06:59.521694 | 2025-11-06 00:06:59.521836 | TASK [Disable Fedora Modular] 2025-11-06 00:07:00.284234 | controller | changed 2025-11-06 00:07:00.293681 | 2025-11-06 00:07:00.293847 | TASK [Enable EPEL] 2025-11-06 00:07:00.319605 | controller | skipping: Conditional result was False 2025-11-06 00:07:00.332661 | 2025-11-06 00:07:00.332845 | TASK [Register the RHEL node] 2025-11-06 00:07:00.490130 | 2025-11-06 00:07:00.490297 | TASK [Show the subscription-manager status] 2025-11-06 00:07:00.674817 | controller | skipping: Conditional result was False 2025-11-06 00:07:00.682780 | 2025-11-06 00:07:00.682892 | TASK [Enable EPEL on RHEL] 2025-11-06 00:07:00.814138 | controller | skipping: Conditional result was False 2025-11-06 00:07:00.834433 | 2025-11-06 00:07:00.834636 | TASK [Install git and tox] 2025-11-06 00:08:26.973450 | controller | changed 2025-11-06 00:08:26.980762 | 2025-11-06 00:08:26.980839 | TASK [include_role : prepare-workspace] 2025-11-06 00:08:27.001720 | controller | ok 2025-11-06 00:08:27.038995 | 2025-11-06 00:08:27.039118 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-11-06 00:08:27.643648 | controller | ok 2025-11-06 00:08:27.650093 | 2025-11-06 00:08:27.650179 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-11-06 00:08:42.254412 | controller | Output suppressed because no_log was given 2025-11-06 00:08:42.265975 | 2025-11-06 00:08:42.266088 | TASK [include_role : prepare-workspace-openshift] 2025-11-06 00:08:42.320608 | controller | skipping: Conditional result was False 2025-11-06 00:08:42.385252 | 2025-11-06 00:08:42.385331 | PLAY [all:!appliance] 2025-11-06 00:08:42.402579 | 2025-11-06 00:08:42.402684 | TASK [Run add-build-sshkey role (RSA)] 2025-11-06 00:08:42.424263 | controller | ok 2025-11-06 00:08:42.443339 | 2025-11-06 00:08:42.443454 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-06 00:08:42.671805 | controller -> localhost | ok 2025-11-06 00:08:42.680997 | 2025-11-06 00:08:42.681110 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-06 00:08:42.702582 | controller | ok 2025-11-06 00:08:42.721099 | controller | included: /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-06 00:08:42.728000 | 2025-11-06 00:08:42.728106 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-06 00:08:43.172377 | controller -> localhost | Generating public/private rsa key pair. 2025-11-06 00:08:43.172563 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/work/9fd2c594845b4b98afbb28f82942d3b5_id_rsa. 2025-11-06 00:08:43.172594 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/work/9fd2c594845b4b98afbb28f82942d3b5_id_rsa.pub. 2025-11-06 00:08:43.172617 | controller -> localhost | The key fingerprint is: 2025-11-06 00:08:43.172639 | controller -> localhost | SHA256:+sqnoIS5QPBAz5SigDPMceNaqDl0LyE4BrEXkrT8fHs zuul-build-sshkey 2025-11-06 00:08:43.172660 | controller -> localhost | The key's randomart image is: 2025-11-06 00:08:43.172680 | controller -> localhost | +---[RSA 2048]----+ 2025-11-06 00:08:43.172701 | controller -> localhost | |O*o+. | 2025-11-06 00:08:43.172737 | controller -> localhost | |@*Oo. | 2025-11-06 00:08:43.172763 | controller -> localhost | |OXoB | 2025-11-06 00:08:43.172784 | controller -> localhost | |**B o | 2025-11-06 00:08:43.172804 | controller -> localhost | |+o.+ o S | 2025-11-06 00:08:43.172836 | controller -> localhost | |.+ o .. | 2025-11-06 00:08:43.172862 | controller -> localhost | |+ . ...E | 2025-11-06 00:08:43.172883 | controller -> localhost | |.o . o... | 2025-11-06 00:08:43.172903 | controller -> localhost | |. . ++. | 2025-11-06 00:08:43.172926 | controller -> localhost | +----[SHA256]-----+ 2025-11-06 00:08:43.172973 | controller -> localhost | ok: Runtime: 0:00:00.046685 2025-11-06 00:08:43.179863 | 2025-11-06 00:08:43.179931 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-06 00:08:43.210123 | controller | ok 2025-11-06 00:08:43.240971 | controller | included: /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-06 00:08:43.250422 | 2025-11-06 00:08:43.250517 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-06 00:08:43.274817 | controller | skipping: Conditional result was False 2025-11-06 00:08:43.283408 | 2025-11-06 00:08:43.283520 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-06 00:08:44.005503 | controller | changed 2025-11-06 00:08:44.021119 | 2025-11-06 00:08:44.021303 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-06 00:08:44.382316 | controller | ok 2025-11-06 00:08:44.388635 | 2025-11-06 00:08:44.388762 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-06 00:08:45.806784 | controller | changed 2025-11-06 00:08:45.819688 | 2025-11-06 00:08:45.819942 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-06 00:08:47.467025 | controller | changed 2025-11-06 00:08:47.473357 | 2025-11-06 00:08:47.473458 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-06 00:08:47.498342 | controller | skipping: Conditional result was False 2025-11-06 00:08:47.506303 | 2025-11-06 00:08:47.506394 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-06 00:08:47.929251 | controller -> localhost | changed 2025-11-06 00:08:47.945449 | 2025-11-06 00:08:47.945553 | TASK [add-build-sshkey : Add back temp key] 2025-11-06 00:08:48.306417 | controller -> localhost | Identity added: /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/work/9fd2c594845b4b98afbb28f82942d3b5_id_rsa (zuul-build-sshkey) 2025-11-06 00:08:48.306667 | controller -> localhost | ok: Runtime: 0:00:00.018629 2025-11-06 00:08:48.315835 | 2025-11-06 00:08:48.315923 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-06 00:08:48.846600 | controller | ok 2025-11-06 00:08:48.853012 | 2025-11-06 00:08:48.853084 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-06 00:08:48.897349 | controller | skipping: Conditional result was False 2025-11-06 00:08:48.916068 | 2025-11-06 00:08:48.916227 | TASK [Run add-build-sshkey role (ECDSA)] 2025-11-06 00:08:48.952314 | controller | ok 2025-11-06 00:08:48.979219 | 2025-11-06 00:08:48.979364 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-11-06 00:08:49.259881 | controller -> localhost | ok 2025-11-06 00:08:49.274554 | 2025-11-06 00:08:49.274788 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-11-06 00:08:49.304051 | controller | ok 2025-11-06 00:08:49.327262 | controller | included: /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-11-06 00:08:49.334327 | 2025-11-06 00:08:49.334450 | TASK [add-build-sshkey : Create Temp SSH key] 2025-11-06 00:08:49.695381 | controller -> localhost | Generating public/private ecdsa key pair. 2025-11-06 00:08:49.695617 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/work/9fd2c594845b4b98afbb28f82942d3b5_id_ecdsa. 2025-11-06 00:08:49.695656 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/work/9fd2c594845b4b98afbb28f82942d3b5_id_ecdsa.pub. 2025-11-06 00:08:49.695696 | controller -> localhost | The key fingerprint is: 2025-11-06 00:08:49.695743 | controller -> localhost | SHA256:xXWiNHWqApxxvyA+hlH6b8gBkzwsNfIKqX/f6Hg4CiE zuul-build-sshkey 2025-11-06 00:08:49.695776 | controller -> localhost | The key's randomart image is: 2025-11-06 00:08:49.695804 | controller -> localhost | +---[ECDSA 521]---+ 2025-11-06 00:08:49.695841 | controller -> localhost | | . o o . o.+ o | 2025-11-06 00:08:49.695869 | controller -> localhost | | . * * + + + = | 2025-11-06 00:08:49.695895 | controller -> localhost | |o . @ = . = . | 2025-11-06 00:08:49.695920 | controller -> localhost | |.. o O o o o | 2025-11-06 00:08:49.695944 | controller -> localhost | |E . . * S o | 2025-11-06 00:08:49.695967 | controller -> localhost | |.o o = . | 2025-11-06 00:08:49.695989 | controller -> localhost | |. . ..o o | 2025-11-06 00:08:49.696012 | controller -> localhost | | . .oo.+ | 2025-11-06 00:08:49.696035 | controller -> localhost | | ...++ . | 2025-11-06 00:08:49.696058 | controller -> localhost | +----[SHA256]-----+ 2025-11-06 00:08:49.696114 | controller -> localhost | ok: Runtime: 0:00:00.012577 2025-11-06 00:08:49.708640 | 2025-11-06 00:08:49.708788 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-11-06 00:08:49.744514 | controller | ok 2025-11-06 00:08:49.759594 | controller | included: /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-11-06 00:08:49.774112 | 2025-11-06 00:08:49.774243 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-11-06 00:08:49.799601 | controller | skipping: Conditional result was False 2025-11-06 00:08:49.808798 | 2025-11-06 00:08:49.808907 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-11-06 00:08:50.282982 | controller | changed 2025-11-06 00:08:50.297275 | 2025-11-06 00:08:50.297417 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-11-06 00:08:50.647666 | controller | ok 2025-11-06 00:08:50.661879 | 2025-11-06 00:08:50.662012 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-11-06 00:08:52.062529 | controller | changed 2025-11-06 00:08:52.072350 | 2025-11-06 00:08:52.072498 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-11-06 00:08:53.711405 | controller | changed 2025-11-06 00:08:53.721377 | 2025-11-06 00:08:53.721498 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-11-06 00:08:53.747616 | controller | skipping: Conditional result was False 2025-11-06 00:08:53.763218 | 2025-11-06 00:08:53.763607 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-11-06 00:08:54.045280 | controller -> localhost | changed 2025-11-06 00:08:54.089925 | 2025-11-06 00:08:54.090046 | TASK [add-build-sshkey : Add back temp key] 2025-11-06 00:08:54.481819 | controller -> localhost | Identity added: /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/work/9fd2c594845b4b98afbb28f82942d3b5_id_ecdsa (zuul-build-sshkey) 2025-11-06 00:08:54.482101 | controller -> localhost | ok: Runtime: 0:00:00.015354 2025-11-06 00:08:54.490071 | 2025-11-06 00:08:54.490157 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-11-06 00:08:54.905818 | controller | ok 2025-11-06 00:08:54.916574 | 2025-11-06 00:08:54.916704 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-11-06 00:08:54.946616 | controller | skipping: Conditional result was False 2025-11-06 00:08:54.970969 | 2025-11-06 00:08:54.971167 | TASK [include_role : remove-zuul-sshkey] 2025-11-06 00:08:55.000494 | controller | skipping: Conditional result was False 2025-11-06 00:08:55.010928 | 2025-11-06 00:08:55.011051 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-11-06 00:08:55.359606 | controller | ok: "logs" 2025-11-06 00:08:55.359884 | controller | ok: All items complete 2025-11-06 00:08:55.359920 | 2025-11-06 00:08:55.673627 | controller | ok: "artifacts" 2025-11-06 00:08:55.965210 | controller | ok: "docs" 2025-11-06 00:08:55.978539 | 2025-11-06 00:08:55.978782 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-11-06 00:08:56.332292 | controller | changed: "logs" 2025-11-06 00:08:56.632789 | controller | changed: "artifacts" 2025-11-06 00:08:56.910232 | controller | changed: "docs" 2025-11-06 00:08:56.977292 | 2025-11-06 00:08:56.977471 | PLAY RECAP 2025-11-06 00:08:56.977540 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-11-06 00:08:56.977573 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-11-06 00:08:56.977592 | 2025-11-06 00:08:57.125244 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-11-06 00:08:57.127117 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-06 00:08:57.783407 | 2025-11-06 00:08:57.783756 | PLAY [all] 2025-11-06 00:08:57.826670 | 2025-11-06 00:08:57.826937 | TASK [Install binary dependencies] 2025-11-06 00:08:57.880259 | controller | ok 2025-11-06 00:08:57.901332 | 2025-11-06 00:08:57.901515 | TASK [bindep : Include find tasks] 2025-11-06 00:08:57.931611 | controller | ok 2025-11-06 00:08:57.942566 | controller | included: /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-11-06 00:08:57.948891 | 2025-11-06 00:08:57.948964 | TASK [bindep : Look for bindep.txt] 2025-11-06 00:08:58.500143 | controller | ok 2025-11-06 00:08:58.507527 | 2025-11-06 00:08:58.507648 | TASK [bindep : Define bindep_file fact] 2025-11-06 00:08:58.522250 | controller | skipping: Conditional result was False 2025-11-06 00:08:58.531291 | 2025-11-06 00:08:58.531448 | TASK [bindep : Look for other-requirements.txt] 2025-11-06 00:08:58.856829 | controller | ok 2025-11-06 00:08:58.862552 | 2025-11-06 00:08:58.862654 | TASK [bindep : Define bindep_file fact] 2025-11-06 00:08:58.890971 | controller | skipping: Conditional result was False 2025-11-06 00:08:58.899258 | 2025-11-06 00:08:58.899366 | TASK [bindep : Look for bindep fallback file] 2025-11-06 00:08:58.925396 | controller | skipping: Conditional result was False 2025-11-06 00:08:58.934142 | 2025-11-06 00:08:58.934249 | TASK [bindep : Define bindep_file fact] 2025-11-06 00:08:58.959951 | controller | skipping: Conditional result was False 2025-11-06 00:08:58.969131 | 2025-11-06 00:08:58.969246 | TASK [bindep : Include bindep tasks] 2025-11-06 00:08:58.994966 | controller | skipping: Conditional result was False 2025-11-06 00:08:59.005120 | 2025-11-06 00:08:59.005220 | TASK [bindep : Include install tasks] 2025-11-06 00:08:59.030658 | controller | skipping: Conditional result was False 2025-11-06 00:08:59.039392 | 2025-11-06 00:08:59.039535 | LOOP [bindep : Include package tasks] 2025-11-06 00:08:59.099977 | 2025-11-06 00:08:59.100193 | TASK [Run test-setup role] 2025-11-06 00:08:59.122440 | controller | ok 2025-11-06 00:08:59.152983 | 2025-11-06 00:08:59.153131 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-11-06 00:08:59.481977 | controller | ok 2025-11-06 00:08:59.488648 | 2025-11-06 00:08:59.488745 | TASK [test-setup : Run tools/test-setup.sh] 2025-11-06 00:08:59.624972 | controller | skipping: Conditional result was False 2025-11-06 00:08:59.677818 | 2025-11-06 00:08:59.677966 | PLAY RECAP 2025-11-06 00:08:59.678031 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-06 00:08:59.678067 | 2025-11-06 00:08:59.801559 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-11-06 00:08:59.802880 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-06 00:09:00.444340 | 2025-11-06 00:09:00.444463 | PLAY [controller] 2025-11-06 00:09:00.464305 | 2025-11-06 00:09:00.464392 | TASK [Create the /root directory] 2025-11-06 00:09:01.306178 | controller | ok 2025-11-06 00:09:01.321281 | 2025-11-06 00:09:01.321507 | TASK [Install glibc-langpack-en] 2025-11-06 00:09:13.316605 | controller | ok: Nothing to do 2025-11-06 00:09:13.324001 | 2025-11-06 00:09:13.324127 | TASK [Ensure controller directory exists] 2025-11-06 00:09:13.795401 | controller | changed 2025-11-06 00:09:13.805868 | 2025-11-06 00:09:13.806009 | TASK [Install container runtime] 2025-11-06 00:09:13.881051 | controller | ok 2025-11-06 00:09:13.925974 | 2025-11-06 00:09:13.926125 | LOOP [ensure-podman : Find distribution installation] 2025-11-06 00:09:13.954089 | controller | ok: "/var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-11-06 00:09:13.961611 | controller | included: /var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-11-06 00:09:13.969259 | 2025-11-06 00:09:13.969365 | TASK [ensure-podman : Install podman (RedHat)] 2025-11-06 00:10:32.280754 | controller | changed 2025-11-06 00:10:32.287281 | 2025-11-06 00:10:32.287375 | TASK [ensure-podman : Fetch podman version] 2025-11-06 00:10:33.026983 | controller | Client: Podman Engine 2025-11-06 00:10:33.027059 | controller | Version: 4.6.2 2025-11-06 00:10:33.027089 | controller | API Version: 4.6.2 2025-11-06 00:10:33.027115 | controller | Go Version: go1.19.12 2025-11-06 00:10:33.027153 | controller | Built: Mon Aug 28 19:38:31 2023 2025-11-06 00:10:33.027181 | controller | OS/Arch: linux/amd64 2025-11-06 00:10:33.438896 | controller | ok: Runtime: 0:00:00.220634 2025-11-06 00:10:33.448483 | 2025-11-06 00:10:33.448666 | TASK [ensure-podman : Print podman version installed] 2025-11-06 00:10:33.481776 | Podman version: Client: Podman Engine 2025-11-06 00:10:33.481981 | Version: 4.6.2 2025-11-06 00:10:33.482021 | API Version: 4.6.2 2025-11-06 00:10:33.482047 | Go Version: go1.19.12 2025-11-06 00:10:33.482069 | Built: Mon Aug 28 19:38:31 2023 2025-11-06 00:10:33.482091 | OS/Arch: linux/amd64 2025-11-06 00:10:33.490224 | 2025-11-06 00:10:33.490347 | TASK [ensure-podman : Validate podman engine] 2025-11-06 00:10:33.622894 | controller | skipping: Conditional result was False 2025-11-06 00:10:33.632763 | 2025-11-06 00:10:33.633045 | TASK [ensure-podman : Set up docker compatability socket] 2025-11-06 00:10:33.648226 | controller | skipping: Conditional result was False 2025-11-06 00:10:33.665884 | 2025-11-06 00:10:33.666019 | TASK [Ensure python3.8 is present] 2025-11-06 00:10:33.680978 | controller | skipping: Conditional result was False 2025-11-06 00:10:33.687764 | 2025-11-06 00:10:33.687883 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-11-06 00:10:33.712247 | controller | ok 2025-11-06 00:10:33.738527 | 2025-11-06 00:10:33.738649 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-11-06 00:10:37.558840 | controller | ok: Nothing to do 2025-11-06 00:10:37.564836 | 2025-11-06 00:10:37.564945 | TASK [our-ensure-python : Also install python3-devel] 2025-11-06 00:10:50.722383 | controller | changed 2025-11-06 00:10:50.741073 | 2025-11-06 00:10:50.741223 | TASK [Run ensure-virtualenv role] 2025-11-06 00:10:50.765283 | controller | ok 2025-11-06 00:10:50.802357 | 2025-11-06 00:10:50.802508 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-11-06 00:10:51.171723 | controller | /usr/bin/virtualenv 2025-11-06 00:10:51.444520 | controller | ok: Runtime: 0:00:00.004313 2025-11-06 00:10:51.451715 | 2025-11-06 00:10:51.451849 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-11-06 00:10:51.471831 | controller | skipping: Conditional result was False 2025-11-06 00:10:51.472119 | controller | ok: All items complete 2025-11-06 00:10:51.472149 | 2025-11-06 00:10:51.488796 | 2025-11-06 00:10:51.488927 | TASK [Find the full path of the Python interpreter] 2025-11-06 00:10:51.904848 | controller | /usr/bin/python3 2025-11-06 00:10:52.127862 | controller | ok 2025-11-06 00:10:52.136615 | 2025-11-06 00:10:52.136804 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-11-06 00:10:53.564444 | controller | created virtual environment CPython3.11.0.final.0-64 in 760ms 2025-11-06 00:10:53.603493 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-11-06 00:10:53.603546 | 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-worker/.local/share/virtualenv) 2025-11-06 00:10:53.603564 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-11-06 00:10:53.603586 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-11-06 00:10:53.793578 | controller | changed 2025-11-06 00:10:53.799954 | 2025-11-06 00:10:53.800018 | TASK [Set selinux package] 2025-11-06 00:10:53.835913 | controller | ok 2025-11-06 00:10:53.847650 | 2025-11-06 00:10:53.847828 | TASK [Set selinux package (Fedora)] 2025-11-06 00:10:53.892081 | controller | ok 2025-11-06 00:10:53.897365 | 2025-11-06 00:10:53.897442 | TASK [Install selinux into virtualenv] 2025-11-06 00:10:56.558448 | controller | Collecting selinux-please-lie-to-me 2025-11-06 00:10:56.646789 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-11-06 00:10:57.177820 | controller | Collecting setuptools<50.0.0 2025-11-06 00:10:57.200809 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-11-06 00:10:57.324013 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.9 MB/s eta 0:00:00 2025-11-06 00:10:57.481140 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-11-06 00:10:57.481592 | controller | Attempting uninstall: setuptools 2025-11-06 00:10:57.486537 | controller | Found existing installation: setuptools 62.6.0 2025-11-06 00:10:57.598061 | controller | Uninstalling setuptools-62.6.0: 2025-11-06 00:10:57.613274 | controller | Successfully uninstalled setuptools-62.6.0 2025-11-06 00:10:58.377692 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-11-06 00:10:58.591056 | controller | 2025-11-06 00:10:58.804348 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-06 00:10:58.804399 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-06 00:10:59.061890 | controller | ok: Runtime: 0:00:04.422234 2025-11-06 00:10:59.067811 | 2025-11-06 00:10:59.067889 | TASK [Install pytest-forked into virtualenv] 2025-11-06 00:11:00.271980 | controller | Collecting pytest-forked 2025-11-06 00:11:00.356823 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-11-06 00:11:00.417128 | controller | Collecting py 2025-11-06 00:11:00.429407 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-11-06 00:11:00.468281 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.8 MB/s eta 0:00:00 2025-11-06 00:11:00.643874 | controller | Collecting pytest>=3.10 2025-11-06 00:11:00.656091 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-11-06 00:11:00.721734 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.8 MB/s eta 0:00:00 2025-11-06 00:11:00.778296 | controller | Collecting iniconfig>=1 2025-11-06 00:11:00.791969 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-11-06 00:11:00.919658 | controller | Collecting packaging>=20 2025-11-06 00:11:00.932947 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-11-06 00:11:00.946791 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.5 MB/s eta 0:00:00 2025-11-06 00:11:00.993474 | controller | Collecting pluggy<2,>=1.5 2025-11-06 00:11:01.005505 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-11-06 00:11:01.080361 | controller | Collecting pygments>=2.7.2 2025-11-06 00:11:01.092150 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-11-06 00:11:01.211808 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.5 MB/s eta 0:00:00 2025-11-06 00:11:01.396514 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-11-06 00:11:03.943095 | controller | Successfully installed iniconfig-2.3.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-11-06 00:11:03.959534 | controller | 2025-11-06 00:11:04.148831 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-11-06 00:11:04.148886 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-11-06 00:11:04.213442 | controller | ok: Runtime: 0:00:04.610419 2025-11-06 00:11:04.221431 | 2025-11-06 00:11:04.221522 | TASK [Update pip] 2025-11-06 00:11:05.361596 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-11-06 00:11:05.630107 | controller | Collecting pip 2025-11-06 00:11:05.728132 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-11-06 00:11:05.937397 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.6 MB/s eta 0:00:00 2025-11-06 00:11:06.101895 | controller | Installing collected packages: pip 2025-11-06 00:11:06.102769 | controller | Attempting uninstall: pip 2025-11-06 00:11:06.112926 | controller | Found existing installation: pip 22.2.2 2025-11-06 00:11:06.440607 | controller | Uninstalling pip-22.2.2: 2025-11-06 00:11:06.476573 | controller | Successfully uninstalled pip-22.2.2 2025-11-06 00:11:08.192778 | controller | Successfully installed pip-25.3 2025-11-06 00:11:08.865411 | controller | ok: Runtime: 0:00:03.596226 2025-11-06 00:11:08.871228 | 2025-11-06 00:11:08.871294 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-11-06 00:11:09.377926 | controller | changed 2025-11-06 00:11:09.387564 | 2025-11-06 00:11:09.387687 | TASK [Install ansible into virtualenv] 2025-11-06 00:11:10.342483 | controller | Processing ./src/github.com/ansible/ansible 2025-11-06 00:11:10.348560 | controller | Installing build dependencies: started 2025-11-06 00:11:12.162849 | controller | Installing build dependencies: finished with status 'done' 2025-11-06 00:11:13.651971 | controller | Getting requirements to build wheel: started 2025-11-06 00:11:13.652042 | controller | Getting requirements to build wheel: finished with status 'done' 2025-11-06 00:11:13.652137 | controller | Preparing metadata (pyproject.toml): started 2025-11-06 00:11:14.569979 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-11-06 00:11:14.573064 | 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-06 00:11:14.577959 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-11-06 00:11:15.042311 | controller | ERROR 2025-11-06 00:11:15.042999 | controller | { 2025-11-06 00:11:15.043062 | controller | "delta": "0:00:04.924008", 2025-11-06 00:11:15.043095 | controller | "end": "2025-11-06 00:11:14.719825", 2025-11-06 00:11:15.043122 | controller | "msg": "non-zero return code", 2025-11-06 00:11:15.043164 | controller | "rc": 1, 2025-11-06 00:11:15.043188 | controller | "start": "2025-11-06 00:11:09.795817" 2025-11-06 00:11:15.043211 | controller | } failure 2025-11-06 00:11:15.045212 | 2025-11-06 00:11:15.045274 | PLAY RECAP 2025-11-06 00:11:15.045328 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-11-06 00:11:15.045356 | 2025-11-06 00:11:15.166315 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-11-06 00:11:15.167921 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-06 00:11:15.892055 | 2025-11-06 00:11:15.892213 | PLAY [all] 2025-11-06 00:11:15.926269 | 2025-11-06 00:11:15.926443 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-11-06 00:11:16.761889 | controller | changed: non-zero return code 2025-11-06 00:11:16.775786 | 2025-11-06 00:11:16.776060 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-11-06 00:11:16.806757 | controller | skipping: Conditional result was False 2025-11-06 00:11:16.822635 | 2025-11-06 00:11:16.822998 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-11-06 00:11:16.853387 | 2025-11-06 00:11:16.853633 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-11-06 00:11:16.878220 | 2025-11-06 00:11:16.878566 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-11-06 00:11:16.904741 | controller | skipping: Conditional result was False 2025-11-06 00:11:16.911593 | 2025-11-06 00:11:16.911671 | LOOP [fetch-subunit-output : Generate subunit file] 2025-11-06 00:11:16.933965 | 2025-11-06 00:11:16.934118 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-11-06 00:11:16.948162 | controller | skipping: Conditional result was False 2025-11-06 00:11:16.954976 | 2025-11-06 00:11:16.955052 | TASK [fetch-subunit-output : Remove the temporary file] 2025-11-06 00:11:16.969355 | controller | skipping: Conditional result was False 2025-11-06 00:11:16.976195 | 2025-11-06 00:11:16.976275 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-11-06 00:11:16.990596 | controller | skipping: Conditional result was False 2025-11-06 00:11:17.019429 | 2025-11-06 00:11:17.019533 | PLAY RECAP 2025-11-06 00:11:17.019579 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-11-06 00:11:17.019600 | 2025-11-06 00:11:17.123600 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-11-06 00:11:17.124977 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-11-06 00:11:17.733017 | 2025-11-06 00:11:17.733152 | PLAY [all:!appliance*] 2025-11-06 00:11:17.756993 | 2025-11-06 00:11:17.757118 | TASK [unregister the node] 2025-11-06 00:11:17.890715 | controller | skipping: Conditional result was False 2025-11-06 00:11:17.896989 | 2025-11-06 00:11:17.897106 | TASK [include_role : fetch-output] 2025-11-06 00:11:17.927013 | controller | ok 2025-11-06 00:11:17.950777 | 2025-11-06 00:11:17.950910 | TASK [fetch-output : Set log path for multiple nodes] 2025-11-06 00:11:18.007383 | controller | skipping: Conditional result was False 2025-11-06 00:11:18.013391 | 2025-11-06 00:11:18.013476 | TASK [fetch-output : Set log path for single node] 2025-11-06 00:11:18.053296 | controller | ok 2025-11-06 00:11:18.059043 | 2025-11-06 00:11:18.059172 | LOOP [fetch-output : Ensure local output dirs] 2025-11-06 00:11:18.454050 | controller -> localhost | ok: "/var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/work/logs" 2025-11-06 00:11:18.736160 | controller -> localhost | changed: "/var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/work/artifacts" 2025-11-06 00:11:18.989376 | controller -> localhost | changed: "/var/lib/zuul/builds/9fd2c594845b4b98afbb28f82942d3b5/work/docs" 2025-11-06 00:11:18.999645 | 2025-11-06 00:11:18.999789 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-11-06 00:11:20.276466 | controller | changed: 2025-11-06 00:11:20.276667 | controller | .d..t...... ./ 2025-11-06 00:11:20.276707 | controller | cd+++++++++ controller/ 2025-11-06 00:11:20.276773 | controller | changed: All items complete 2025-11-06 00:11:20.276796 | 2025-11-06 00:11:21.413782 | controller | changed: .d..t...... ./ 2025-11-06 00:11:22.564996 | controller | changed: .d..t...... ./ 2025-11-06 00:11:22.603886 | 2025-11-06 00:11:22.604097 | TASK [include_role : fetch-output-openshift] 2025-11-06 00:11:22.631571 | controller | skipping: Conditional result was False 2025-11-06 00:11:22.639235 | 2025-11-06 00:11:22.639337 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-11-06 00:11:22.677148 | controller | skipping: Conditional result was False 2025-11-06 00:11:22.693157 | controller | skipping: Conditional result was False 2025-11-06 00:11:22.724878 | 2025-11-06 00:11:22.724993 | PLAY [localhost] 2025-11-06 00:11:22.738448 | 2025-11-06 00:11:22.738555 | TASK [Run Zuul manifest role] 2025-11-06 00:11:22.765997 | localhost | ok 2025-11-06 00:11:22.806092 | 2025-11-06 00:11:22.806308 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-11-06 00:11:23.236025 | localhost | changed 2025-11-06 00:11:23.241519 | 2025-11-06 00:11:23.241603 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-11-06 00:11:23.270635 | localhost | ok 2025-11-06 00:11:23.279180 | 2025-11-06 00:11:23.279251 | TASK [Set zuul-log-path fact] 2025-11-06 00:11:23.298263 | localhost | ok 2025-11-06 00:11:23.313617 | 2025-11-06 00:11:23.313720 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-11-06 00:11:23.342227 | localhost | ok 2025-11-06 00:11:23.351871 | 2025-11-06 00:11:23.351956 | LOOP [Run upload-logs-swift role] 2025-11-06 00:11:23.378218 | localhost | Output suppressed because no_log was given 2025-11-06 00:11:23.406162 | 2025-11-06 00:11:23.406307 | TASK [Set zuul-log-path fact] 2025-11-06 00:11:23.441272 | localhost | skipping: Conditional result was False 2025-11-06 00:11:23.446249 | 2025-11-06 00:11:23.446321 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-11-06 00:11:23.868676 | localhost -> localhost | ok: Runtime: 0:00:00.009306 2025-11-06 00:11:23.875715 | 2025-11-06 00:11:23.875865 | TASK [upload-logs-swift : Upload logs to swift]