2025-12-22 00:20:55.232374 | Job console starting... 2025-12-22 00:20:55.244445 | Updating repositories 2025-12-22 00:20:55.358155 | Preparing job workspace 2025-12-22 00:21:00.141392 | Running Ansible setup... 2025-12-22 00:21:05.046138 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-22 00:21:05.643336 | 2025-12-22 00:21:05.643487 | PLAY [localhost] 2025-12-22 00:21:05.652769 | 2025-12-22 00:21:05.652856 | TASK [Gathering Facts] 2025-12-22 00:21:06.745283 | localhost | ok 2025-12-22 00:21:06.774407 | 2025-12-22 00:21:06.774512 | TASK [Setup log path fact] 2025-12-22 00:21:06.795935 | localhost | ok 2025-12-22 00:21:06.812967 | 2025-12-22 00:21:06.813134 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-22 00:21:06.856492 | localhost | ok 2025-12-22 00:21:06.870629 | 2025-12-22 00:21:06.870740 | TASK [emit-job-header : Print job information] 2025-12-22 00:21:06.924627 | # Job Information 2025-12-22 00:21:06.924925 | Ansible Version: 2.15.12 2025-12-22 00:21:06.925015 | Job: ansible-test-sanity-docker-milestone 2025-12-22 00:21:06.925063 | Pipeline: periodic 2025-12-22 00:21:06.925105 | Executor: ze02.softwarefactory-project.io 2025-12-22 00:21:06.925144 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-22 00:21:06.925190 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/b35/ansible/b357f814016d4e3a96ce8fbfc15b6794/ 2025-12-22 00:21:06.925231 | Event ID: 7f35c592378340c19748c21b5a64baf3 2025-12-22 00:21:06.933872 | 2025-12-22 00:21:06.934015 | LOOP [emit-job-header : Print node information] 2025-12-22 00:21:07.060533 | localhost | ok: 2025-12-22 00:21:07.060838 | localhost | # Node Information 2025-12-22 00:21:07.060915 | localhost | Inventory Hostname: controller 2025-12-22 00:21:07.060960 | localhost | Hostname: np0005568487 2025-12-22 00:21:07.061002 | localhost | Username: zuul 2025-12-22 00:21:07.061050 | localhost | Distro: Fedora 37 2025-12-22 00:21:07.061095 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-22 00:21:07.061132 | localhost | Region: ca-ymq-1 2025-12-22 00:21:07.061169 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-22 00:21:07.061204 | localhost | Product Name: OpenStack Nova 2025-12-22 00:21:07.061240 | localhost | Interface IP: 162.253.55.212 2025-12-22 00:21:07.083194 | 2025-12-22 00:21:07.083401 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-22 00:21:07.456790 | localhost -> localhost | changed 2025-12-22 00:21:07.464243 | 2025-12-22 00:21:07.464333 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-22 00:21:08.386032 | localhost -> localhost | changed 2025-12-22 00:21:08.427904 | 2025-12-22 00:21:08.428000 | PLAY [all:!appliance*] 2025-12-22 00:21:08.449603 | 2025-12-22 00:21:08.449709 | TASK [include_role : start-zuul-console] 2025-12-22 00:21:08.481000 | controller | ok 2025-12-22 00:21:08.500387 | 2025-12-22 00:21:08.500524 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-22 00:21:08.897951 | controller | ok 2025-12-22 00:21:08.912891 | 2025-12-22 00:21:08.913022 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-22 00:21:46.909370 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-22 00:21:46.923296 | 2025-12-22 00:21:46.923427 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-22 00:21:47.464344 | controller | skipping: Conditional result was False 2025-12-22 00:21:47.479881 | 2025-12-22 00:21:47.480033 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-22 00:21:47.517592 | controller | skipping: Conditional result was False 2025-12-22 00:21:47.531555 | 2025-12-22 00:21:47.531762 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-22 00:21:47.558758 | controller | skipping: Conditional result was False 2025-12-22 00:21:47.574814 | 2025-12-22 00:21:47.574966 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-22 00:21:47.612196 | controller | skipping: Conditional result was False 2025-12-22 00:21:47.626834 | 2025-12-22 00:21:47.626989 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-22 00:21:47.653986 | controller | skipping: Conditional result was False 2025-12-22 00:21:47.667942 | 2025-12-22 00:21:47.668089 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-22 00:21:47.696619 | controller | skipping: Conditional result was False 2025-12-22 00:21:47.717185 | 2025-12-22 00:21:47.717259 | TASK [Disable Fedora Modular] 2025-12-22 00:21:47.963096 | controller | changed 2025-12-22 00:21:47.971636 | 2025-12-22 00:21:47.971757 | TASK [Enable EPEL] 2025-12-22 00:21:47.997984 | controller | skipping: Conditional result was False 2025-12-22 00:21:48.012966 | 2025-12-22 00:21:48.013178 | TASK [Register the RHEL node] 2025-12-22 00:21:48.576087 | 2025-12-22 00:21:48.576400 | TASK [Show the subscription-manager status] 2025-12-22 00:21:49.133578 | controller | skipping: Conditional result was False 2025-12-22 00:21:49.146977 | 2025-12-22 00:21:49.147116 | TASK [Enable EPEL on RHEL] 2025-12-22 00:21:49.703251 | controller | skipping: Conditional result was False 2025-12-22 00:21:49.712562 | 2025-12-22 00:21:49.712657 | TASK [Install git and tox] 2025-12-22 00:22:34.600024 | controller | changed 2025-12-22 00:22:34.614293 | 2025-12-22 00:22:34.614417 | TASK [include_role : prepare-workspace] 2025-12-22 00:22:34.646468 | controller | ok 2025-12-22 00:22:34.675352 | 2025-12-22 00:22:34.675450 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-22 00:22:34.910895 | controller | ok 2025-12-22 00:22:34.919631 | 2025-12-22 00:22:34.919737 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-22 00:22:46.994936 | controller | Output suppressed because no_log was given 2025-12-22 00:22:47.054242 | 2025-12-22 00:22:47.054395 | TASK [include_role : prepare-workspace-openshift] 2025-12-22 00:22:47.079414 | controller | skipping: Conditional result was False 2025-12-22 00:22:47.110705 | 2025-12-22 00:22:47.110818 | PLAY [all:!appliance] 2025-12-22 00:22:47.130424 | 2025-12-22 00:22:47.130505 | TASK [Run add-build-sshkey role (RSA)] 2025-12-22 00:22:47.153391 | controller | ok 2025-12-22 00:22:47.175796 | 2025-12-22 00:22:47.175903 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-22 00:22:47.444705 | controller -> localhost | ok 2025-12-22 00:22:47.458793 | 2025-12-22 00:22:47.458948 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-22 00:22:47.489877 | controller | ok 2025-12-22 00:22:47.515960 | controller | included: /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-22 00:22:47.524604 | 2025-12-22 00:22:47.524712 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-22 00:22:48.038885 | controller -> localhost | Generating public/private rsa key pair. 2025-12-22 00:22:48.039117 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/work/b357f814016d4e3a96ce8fbfc15b6794_id_rsa. 2025-12-22 00:22:48.039146 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/work/b357f814016d4e3a96ce8fbfc15b6794_id_rsa.pub. 2025-12-22 00:22:48.039166 | controller -> localhost | The key fingerprint is: 2025-12-22 00:22:48.039185 | controller -> localhost | SHA256:zMk2RG44JWaeW6tImKu58cZmQMogBJxervkHSQ6M+qE zuul-build-sshkey 2025-12-22 00:22:48.039204 | controller -> localhost | The key's randomart image is: 2025-12-22 00:22:48.039222 | controller -> localhost | +---[RSA 2048]----+ 2025-12-22 00:22:48.039240 | controller -> localhost | |+ . + o | 2025-12-22 00:22:48.039258 | controller -> localhost | | + . + B | 2025-12-22 00:22:48.039275 | controller -> localhost | |= o = = | 2025-12-22 00:22:48.039292 | controller -> localhost | |+= = X o | 2025-12-22 00:22:48.039309 | controller -> localhost | |B O o . S | 2025-12-22 00:22:48.039337 | controller -> localhost | |++.* . o . | 2025-12-22 00:22:48.039360 | controller -> localhost | |.=o.o . | 2025-12-22 00:22:48.039379 | controller -> localhost | |E=*. . | 2025-12-22 00:22:48.039397 | controller -> localhost | |+=. . | 2025-12-22 00:22:48.039417 | controller -> localhost | +----[SHA256]-----+ 2025-12-22 00:22:48.039471 | controller -> localhost | ok: Runtime: 0:00:00.101490 2025-12-22 00:22:48.046292 | 2025-12-22 00:22:48.046405 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-22 00:22:48.086238 | controller | ok 2025-12-22 00:22:48.095846 | controller | included: /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-22 00:22:48.104907 | 2025-12-22 00:22:48.104966 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-22 00:22:48.129385 | controller | skipping: Conditional result was False 2025-12-22 00:22:48.136488 | 2025-12-22 00:22:48.136557 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-22 00:22:48.591546 | controller | changed 2025-12-22 00:22:48.604842 | 2025-12-22 00:22:48.604973 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-22 00:22:48.851014 | controller | ok 2025-12-22 00:22:48.863420 | 2025-12-22 00:22:48.863552 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-22 00:22:49.494044 | controller | changed 2025-12-22 00:22:49.506923 | 2025-12-22 00:22:49.507059 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-22 00:22:50.107331 | controller | changed 2025-12-22 00:22:50.120856 | 2025-12-22 00:22:50.120991 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-22 00:22:50.148083 | controller | skipping: Conditional result was False 2025-12-22 00:22:50.161773 | 2025-12-22 00:22:50.161909 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-22 00:22:50.554961 | controller -> localhost | changed 2025-12-22 00:22:50.590845 | 2025-12-22 00:22:50.591064 | TASK [add-build-sshkey : Add back temp key] 2025-12-22 00:22:50.895296 | controller -> localhost | Identity added: /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/work/b357f814016d4e3a96ce8fbfc15b6794_id_rsa (zuul-build-sshkey) 2025-12-22 00:22:50.895654 | controller -> localhost | ok: Runtime: 0:00:00.008449 2025-12-22 00:22:50.909513 | 2025-12-22 00:22:50.909641 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-22 00:22:51.255900 | controller | ok 2025-12-22 00:22:51.268441 | 2025-12-22 00:22:51.268568 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-22 00:22:51.295039 | controller | skipping: Conditional result was False 2025-12-22 00:22:51.320770 | 2025-12-22 00:22:51.320900 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-22 00:22:51.357325 | controller | ok 2025-12-22 00:22:51.383655 | 2025-12-22 00:22:51.383776 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-22 00:22:51.642791 | controller -> localhost | ok 2025-12-22 00:22:51.649457 | 2025-12-22 00:22:51.649519 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-22 00:22:51.688945 | controller | ok 2025-12-22 00:22:51.700301 | controller | included: /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-22 00:22:51.706295 | 2025-12-22 00:22:51.706356 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-22 00:22:52.029001 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-22 00:22:52.029293 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/work/b357f814016d4e3a96ce8fbfc15b6794_id_ecdsa. 2025-12-22 00:22:52.029351 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/work/b357f814016d4e3a96ce8fbfc15b6794_id_ecdsa.pub. 2025-12-22 00:22:52.029408 | controller -> localhost | The key fingerprint is: 2025-12-22 00:22:52.029451 | controller -> localhost | SHA256:iTOVXI+NUEWBntBBNEtjNJzf6R8t8jZLWmP4RYy1sKQ zuul-build-sshkey 2025-12-22 00:22:52.029491 | controller -> localhost | The key's randomart image is: 2025-12-22 00:22:52.029530 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-22 00:22:52.029568 | controller -> localhost | | .B&*+. | 2025-12-22 00:22:52.029633 | controller -> localhost | | ..*=X | 2025-12-22 00:22:52.029756 | controller -> localhost | | +o+oo+ ..| 2025-12-22 00:22:52.029804 | controller -> localhost | | o .o + =+.| 2025-12-22 00:22:52.029845 | controller -> localhost | | + S E o..+| 2025-12-22 00:22:52.029883 | controller -> localhost | | o ..oo.| 2025-12-22 00:22:52.029920 | controller -> localhost | | .o=oo| 2025-12-22 00:22:52.029958 | controller -> localhost | | *+o.| 2025-12-22 00:22:52.029994 | controller -> localhost | | ..oo | 2025-12-22 00:22:52.030030 | controller -> localhost | +----[SHA256]-----+ 2025-12-22 00:22:52.030127 | controller -> localhost | ok: Runtime: 0:00:00.007968 2025-12-22 00:22:52.044035 | 2025-12-22 00:22:52.044169 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-22 00:22:52.083704 | controller | ok 2025-12-22 00:22:52.100155 | controller | included: /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-22 00:22:52.114703 | 2025-12-22 00:22:52.114816 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-22 00:22:52.140730 | controller | skipping: Conditional result was False 2025-12-22 00:22:52.151657 | 2025-12-22 00:22:52.151805 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-22 00:22:52.427238 | controller | changed 2025-12-22 00:22:52.433021 | 2025-12-22 00:22:52.433105 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-22 00:22:52.674550 | controller | ok 2025-12-22 00:22:52.688084 | 2025-12-22 00:22:52.688220 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-22 00:22:53.414165 | controller | changed 2025-12-22 00:22:53.427592 | 2025-12-22 00:22:53.427793 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-22 00:22:54.125578 | controller | changed 2025-12-22 00:22:54.133519 | 2025-12-22 00:22:54.133608 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-22 00:22:54.158493 | controller | skipping: Conditional result was False 2025-12-22 00:22:54.206814 | 2025-12-22 00:22:54.206951 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-22 00:22:54.495612 | controller -> localhost | changed 2025-12-22 00:22:54.507045 | 2025-12-22 00:22:54.507111 | TASK [add-build-sshkey : Add back temp key] 2025-12-22 00:22:54.858903 | controller -> localhost | Identity added: /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/work/b357f814016d4e3a96ce8fbfc15b6794_id_ecdsa (zuul-build-sshkey) 2025-12-22 00:22:54.859334 | controller -> localhost | ok: Runtime: 0:00:00.013553 2025-12-22 00:22:54.874275 | 2025-12-22 00:22:54.874411 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-22 00:22:55.097510 | controller | ok 2025-12-22 00:22:55.112508 | 2025-12-22 00:22:55.112647 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-22 00:22:55.149956 | controller | skipping: Conditional result was False 2025-12-22 00:22:55.174696 | 2025-12-22 00:22:55.174839 | TASK [include_role : remove-zuul-sshkey] 2025-12-22 00:22:55.201597 | controller | skipping: Conditional result was False 2025-12-22 00:22:55.215313 | 2025-12-22 00:22:55.215447 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-22 00:22:55.471355 | controller | ok: "logs" 2025-12-22 00:22:55.471836 | controller | ok: All items complete 2025-12-22 00:22:55.471902 | 2025-12-22 00:22:55.664416 | controller | ok: "artifacts" 2025-12-22 00:22:55.864905 | controller | ok: "docs" 2025-12-22 00:22:55.881867 | 2025-12-22 00:22:55.882068 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-22 00:22:56.146384 | controller | changed: "logs" 2025-12-22 00:22:56.348408 | controller | changed: "artifacts" 2025-12-22 00:22:56.563915 | controller | changed: "docs" 2025-12-22 00:22:56.612077 | 2025-12-22 00:22:56.612873 | PLAY RECAP 2025-12-22 00:22:56.613078 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-22 00:22:56.613147 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-22 00:22:56.613190 | 2025-12-22 00:22:56.757987 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-22 00:22:56.759697 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-22 00:22:57.338604 | 2025-12-22 00:22:57.338750 | PLAY [all] 2025-12-22 00:22:57.361069 | 2025-12-22 00:22:57.361156 | TASK [Install binary dependencies] 2025-12-22 00:22:57.431075 | controller | ok 2025-12-22 00:22:57.450355 | 2025-12-22 00:22:57.450432 | TASK [bindep : Include find tasks] 2025-12-22 00:22:57.479592 | controller | ok 2025-12-22 00:22:57.488020 | controller | included: /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-22 00:22:57.494636 | 2025-12-22 00:22:57.494712 | TASK [bindep : Look for bindep.txt] 2025-12-22 00:22:57.858062 | controller | ok 2025-12-22 00:22:57.870848 | 2025-12-22 00:22:57.870988 | TASK [bindep : Define bindep_file fact] 2025-12-22 00:22:57.887452 | controller | skipping: Conditional result was False 2025-12-22 00:22:57.900819 | 2025-12-22 00:22:57.900956 | TASK [bindep : Look for other-requirements.txt] 2025-12-22 00:22:58.112645 | controller | ok 2025-12-22 00:22:58.124984 | 2025-12-22 00:22:58.125119 | TASK [bindep : Define bindep_file fact] 2025-12-22 00:22:58.163167 | controller | skipping: Conditional result was False 2025-12-22 00:22:58.177542 | 2025-12-22 00:22:58.177744 | TASK [bindep : Look for bindep fallback file] 2025-12-22 00:22:58.204960 | controller | skipping: Conditional result was False 2025-12-22 00:22:58.220226 | 2025-12-22 00:22:58.220365 | TASK [bindep : Define bindep_file fact] 2025-12-22 00:22:58.257424 | controller | skipping: Conditional result was False 2025-12-22 00:22:58.270554 | 2025-12-22 00:22:58.270711 | TASK [bindep : Include bindep tasks] 2025-12-22 00:22:58.307463 | controller | skipping: Conditional result was False 2025-12-22 00:22:58.321044 | 2025-12-22 00:22:58.321203 | TASK [bindep : Include install tasks] 2025-12-22 00:22:58.348049 | controller | skipping: Conditional result was False 2025-12-22 00:22:58.362275 | 2025-12-22 00:22:58.362419 | LOOP [bindep : Include package tasks] 2025-12-22 00:22:58.431063 | 2025-12-22 00:22:58.431222 | TASK [Run test-setup role] 2025-12-22 00:22:58.451911 | controller | ok 2025-12-22 00:22:58.468505 | 2025-12-22 00:22:58.468578 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-22 00:22:58.680860 | controller | ok 2025-12-22 00:22:58.696339 | 2025-12-22 00:22:58.696528 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-22 00:22:59.246630 | controller | skipping: Conditional result was False 2025-12-22 00:22:59.302739 | 2025-12-22 00:22:59.302835 | PLAY RECAP 2025-12-22 00:22:59.302899 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-22 00:22:59.302935 | 2025-12-22 00:22:59.406778 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-22 00:22:59.408533 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-22 00:23:00.000575 | 2025-12-22 00:23:00.000729 | PLAY [controller] 2025-12-22 00:23:00.022646 | 2025-12-22 00:23:00.022788 | TASK [Create the /root directory] 2025-12-22 00:23:00.397184 | controller | ok 2025-12-22 00:23:00.410359 | 2025-12-22 00:23:00.410524 | TASK [Install glibc-langpack-en] 2025-12-22 00:23:04.313884 | controller | ok: Nothing to do 2025-12-22 00:23:04.319985 | 2025-12-22 00:23:04.320050 | TASK [Ensure controller directory exists] 2025-12-22 00:23:04.549473 | controller | changed 2025-12-22 00:23:04.563277 | 2025-12-22 00:23:04.563469 | TASK [Install container runtime] 2025-12-22 00:23:04.645115 | controller | ok 2025-12-22 00:23:04.704949 | 2025-12-22 00:23:04.705059 | LOOP [ensure-podman : Find distribution installation] 2025-12-22 00:23:04.740027 | controller | ok: "/var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-22 00:23:04.756517 | controller | included: /var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-22 00:23:04.763171 | 2025-12-22 00:23:04.763252 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-22 00:24:10.805223 | controller | changed 2025-12-22 00:24:10.819516 | 2025-12-22 00:24:10.819649 | TASK [ensure-podman : Fetch podman version] 2025-12-22 00:24:11.341430 | controller | Client: Podman Engine 2025-12-22 00:24:11.341527 | controller | Version: 4.6.2 2025-12-22 00:24:11.341609 | controller | API Version: 4.6.2 2025-12-22 00:24:11.341655 | controller | Go Version: go1.19.12 2025-12-22 00:24:11.341712 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-22 00:24:11.341758 | controller | OS/Arch: linux/amd64 2025-12-22 00:24:11.869070 | controller | ok: Runtime: 0:00:00.186796 2025-12-22 00:24:11.883061 | 2025-12-22 00:24:11.883220 | TASK [ensure-podman : Print podman version installed] 2025-12-22 00:24:11.923084 | Podman version: Client: Podman Engine 2025-12-22 00:24:11.923338 | Version: 4.6.2 2025-12-22 00:24:11.923400 | API Version: 4.6.2 2025-12-22 00:24:11.923446 | Go Version: go1.19.12 2025-12-22 00:24:11.923488 | Built: Mon Aug 28 19:38:31 2023 2025-12-22 00:24:11.923537 | OS/Arch: linux/amd64 2025-12-22 00:24:11.936130 | 2025-12-22 00:24:11.936270 | TASK [ensure-podman : Validate podman engine] 2025-12-22 00:24:12.482249 | controller | skipping: Conditional result was False 2025-12-22 00:24:12.495810 | 2025-12-22 00:24:12.495981 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-22 00:24:12.522997 | controller | skipping: Conditional result was False 2025-12-22 00:24:12.547813 | 2025-12-22 00:24:12.547972 | TASK [Ensure python3.8 is present] 2025-12-22 00:24:12.575498 | controller | skipping: Conditional result was False 2025-12-22 00:24:12.592485 | 2025-12-22 00:24:12.592632 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-22 00:24:12.624003 | controller | ok 2025-12-22 00:24:12.665977 | 2025-12-22 00:24:12.666167 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-22 00:24:14.085940 | controller | ok: Nothing to do 2025-12-22 00:24:14.098551 | 2025-12-22 00:24:14.098719 | TASK [our-ensure-python : Also install python3-devel] 2025-12-22 00:24:23.322003 | controller | changed 2025-12-22 00:24:23.337976 | 2025-12-22 00:24:23.338067 | TASK [Run ensure-virtualenv role] 2025-12-22 00:24:23.360570 | controller | ok 2025-12-22 00:24:23.392991 | 2025-12-22 00:24:23.393136 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-22 00:24:23.656750 | controller | /usr/bin/virtualenv 2025-12-22 00:24:23.965444 | controller | ok: Runtime: 0:00:00.004841 2025-12-22 00:24:23.974355 | 2025-12-22 00:24:23.974460 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-22 00:24:24.009267 | controller | skipping: Conditional result was False 2025-12-22 00:24:24.009816 | controller | ok: All items complete 2025-12-22 00:24:24.009882 | 2025-12-22 00:24:24.042175 | 2025-12-22 00:24:24.042350 | TASK [Find the full path of the Python interpreter] 2025-12-22 00:24:24.271571 | controller | /usr/bin/python3 2025-12-22 00:24:24.584636 | controller | ok 2025-12-22 00:24:24.598557 | 2025-12-22 00:24:24.598745 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-22 00:24:25.641146 | controller | created virtual environment CPython3.11.0.final.0-64 in 584ms 2025-12-22 00:24:25.686524 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-22 00:24:25.686989 | 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-22 00:24:25.687244 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-22 00:24:25.687578 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-22 00:24:26.155865 | controller | changed 2025-12-22 00:24:26.172223 | 2025-12-22 00:24:26.172371 | TASK [Set selinux package] 2025-12-22 00:24:26.213110 | controller | ok 2025-12-22 00:24:26.226969 | 2025-12-22 00:24:26.227103 | TASK [Set selinux package (Fedora)] 2025-12-22 00:24:26.284053 | controller | ok 2025-12-22 00:24:26.291399 | 2025-12-22 00:24:26.291490 | TASK [Install selinux into virtualenv] 2025-12-22 00:25:15.603400 | controller | Collecting selinux-please-lie-to-me 2025-12-22 00:25:27.930595 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-22 00:25:28.239879 | controller | Collecting setuptools<50.0.0 2025-12-22 00:25:28.246268 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-22 00:25:28.285266 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 25.1 MB/s eta 0:00:00 2025-12-22 00:25:28.363680 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-22 00:25:28.363944 | controller | Attempting uninstall: setuptools 2025-12-22 00:25:28.366361 | controller | Found existing installation: setuptools 62.6.0 2025-12-22 00:25:28.427548 | controller | Uninstalling setuptools-62.6.0: 2025-12-22 00:25:28.435699 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-22 00:25:28.780286 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-22 00:25:43.245916 | controller | 2025-12-22 00:25:43.325580 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-22 00:25:43.325630 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-22 00:25:43.380608 | controller | ok: Runtime: 0:01:16.803923 2025-12-22 00:25:43.393952 | 2025-12-22 00:25:43.394108 | TASK [Install pytest-forked into virtualenv] 2025-12-22 00:26:08.232860 | controller | Collecting pytest-forked 2025-12-22 00:26:20.476367 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-22 00:26:20.520105 | controller | Collecting py 2025-12-22 00:26:20.525787 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-22 00:26:20.547560 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 4.8 MB/s eta 0:00:00 2025-12-22 00:26:20.656102 | controller | Collecting pytest>=3.10 2025-12-22 00:26:20.661214 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-22 00:26:20.678193 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 25.8 MB/s eta 0:00:00 2025-12-22 00:26:20.721681 | controller | Collecting iniconfig>=1.0.1 2025-12-22 00:26:20.726129 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-22 00:26:20.770773 | controller | Collecting packaging>=22 2025-12-22 00:26:20.774507 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-22 00:26:20.782315 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 11.2 MB/s eta 0:00:00 2025-12-22 00:26:20.818074 | controller | Collecting pluggy<2,>=1.5 2025-12-22 00:26:20.822343 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-22 00:26:20.875040 | controller | Collecting pygments>=2.7.2 2025-12-22 00:26:20.881482 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-22 00:26:20.914233 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 49.2 MB/s eta 0:00:00 2025-12-22 00:26:20.982370 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-22 00:26:22.051407 | 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-22 00:26:22.060587 | controller | 2025-12-22 00:26:22.136181 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-22 00:26:22.136357 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-22 00:26:22.459154 | controller | ok: Runtime: 0:00:38.518138 2025-12-22 00:26:22.472751 | 2025-12-22 00:26:22.472888 | TASK [Update pip] 2025-12-22 00:26:22.991551 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-22 00:26:32.857650 | controller | Collecting pip 2025-12-22 00:26:45.178893 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-22 00:26:45.248807 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 27.5 MB/s eta 0:00:00 2025-12-22 00:26:45.311570 | controller | Installing collected packages: pip 2025-12-22 00:26:45.311796 | controller | Attempting uninstall: pip 2025-12-22 00:26:45.313985 | controller | Found existing installation: pip 22.2.2 2025-12-22 00:26:45.449709 | controller | Uninstalling pip-22.2.2: 2025-12-22 00:26:45.464621 | controller | Successfully uninstalled pip-22.2.2 2025-12-22 00:26:46.225997 | controller | Successfully installed pip-25.3 2025-12-22 00:26:46.538863 | controller | ok: Runtime: 0:00:23.599653 2025-12-22 00:26:46.551597 | 2025-12-22 00:26:46.551806 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-22 00:26:46.785157 | controller | changed 2025-12-22 00:26:46.798087 | 2025-12-22 00:26:46.798225 | TASK [Install ansible into virtualenv] 2025-12-22 00:26:47.333317 | controller | Processing ./src/github.com/ansible/ansible 2025-12-22 00:26:47.336585 | controller | Installing build dependencies: started 2025-12-22 00:27:08.374123 | controller | Installing build dependencies: finished with status 'done' 2025-12-22 00:27:08.374911 | controller | Getting requirements to build wheel: started 2025-12-22 00:27:09.085784 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-22 00:27:09.086997 | controller | Preparing metadata (pyproject.toml): started 2025-12-22 00:27:09.546395 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-22 00:27:09.551668 | 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-22 00:27:09.557065 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-22 00:27:09.885154 | controller | ERROR 2025-12-22 00:27:09.885485 | controller | { 2025-12-22 00:27:09.885550 | controller | "delta": "0:00:22.559468", 2025-12-22 00:27:09.885593 | controller | "end": "2025-12-22 00:27:09.617262", 2025-12-22 00:27:09.885633 | controller | "msg": "non-zero return code", 2025-12-22 00:27:09.885727 | controller | "rc": 1, 2025-12-22 00:27:09.885771 | controller | "start": "2025-12-22 00:26:47.057794" 2025-12-22 00:27:09.885808 | controller | } failure 2025-12-22 00:27:09.888739 | 2025-12-22 00:27:09.888830 | PLAY RECAP 2025-12-22 00:27:09.888910 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-22 00:27:09.888952 | 2025-12-22 00:27:10.012076 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-22 00:27:10.013245 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-22 00:27:10.671830 | 2025-12-22 00:27:10.671968 | PLAY [all] 2025-12-22 00:27:10.694308 | 2025-12-22 00:27:10.694437 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-22 00:27:10.957511 | controller | changed: non-zero return code 2025-12-22 00:27:10.970412 | 2025-12-22 00:27:10.970587 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-22 00:27:10.997835 | controller | skipping: Conditional result was False 2025-12-22 00:27:11.010447 | 2025-12-22 00:27:11.010612 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-22 00:27:11.050947 | 2025-12-22 00:27:11.051210 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-22 00:27:11.092175 | 2025-12-22 00:27:11.092438 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-22 00:27:11.120852 | controller | skipping: Conditional result was False 2025-12-22 00:27:11.136858 | 2025-12-22 00:27:11.137031 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-22 00:27:11.177810 | 2025-12-22 00:27:11.178093 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-22 00:27:11.215469 | controller | skipping: Conditional result was False 2025-12-22 00:27:11.229068 | 2025-12-22 00:27:11.229231 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-22 00:27:11.266945 | controller | skipping: Conditional result was False 2025-12-22 00:27:11.280335 | 2025-12-22 00:27:11.280498 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-22 00:27:11.307776 | controller | skipping: Conditional result was False 2025-12-22 00:27:11.358221 | 2025-12-22 00:27:11.358350 | PLAY RECAP 2025-12-22 00:27:11.358416 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-22 00:27:11.358453 | 2025-12-22 00:27:11.457009 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-22 00:27:11.457865 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-22 00:27:12.047504 | 2025-12-22 00:27:12.047611 | PLAY [all:!appliance*] 2025-12-22 00:27:12.069627 | 2025-12-22 00:27:12.069743 | TASK [unregister the node] 2025-12-22 00:27:12.602403 | controller | skipping: Conditional result was False 2025-12-22 00:27:12.620839 | 2025-12-22 00:27:12.621040 | TASK [include_role : fetch-output] 2025-12-22 00:27:12.670830 | controller | ok 2025-12-22 00:27:12.708426 | 2025-12-22 00:27:12.708568 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-22 00:27:12.784916 | controller | skipping: Conditional result was False 2025-12-22 00:27:12.794087 | 2025-12-22 00:27:12.794183 | TASK [fetch-output : Set log path for single node] 2025-12-22 00:27:12.853038 | controller | ok 2025-12-22 00:27:12.867199 | 2025-12-22 00:27:12.867364 | LOOP [fetch-output : Ensure local output dirs] 2025-12-22 00:27:13.323989 | controller -> localhost | ok: "/var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/work/logs" 2025-12-22 00:27:13.571335 | controller -> localhost | changed: "/var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/work/artifacts" 2025-12-22 00:27:13.823750 | controller -> localhost | changed: "/var/lib/zuul/builds/b357f814016d4e3a96ce8fbfc15b6794/work/docs" 2025-12-22 00:27:13.843505 | 2025-12-22 00:27:13.843737 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-22 00:27:14.532711 | controller | changed: 2025-12-22 00:27:14.533153 | controller | .d..t...... ./ 2025-12-22 00:27:14.533236 | controller | cd+++++++++ controller/ 2025-12-22 00:27:14.533325 | controller | changed: All items complete 2025-12-22 00:27:14.533376 | 2025-12-22 00:27:15.136257 | controller | changed: .d..t...... ./ 2025-12-22 00:27:15.702327 | controller | changed: .d..t...... ./ 2025-12-22 00:27:15.736411 | 2025-12-22 00:27:15.736562 | TASK [include_role : fetch-output-openshift] 2025-12-22 00:27:15.763379 | controller | skipping: Conditional result was False 2025-12-22 00:27:15.777363 | 2025-12-22 00:27:15.777571 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-22 00:27:15.824017 | controller | skipping: Conditional result was False 2025-12-22 00:27:15.834554 | controller | skipping: Conditional result was False 2025-12-22 00:27:15.891441 | 2025-12-22 00:27:15.891560 | PLAY [localhost] 2025-12-22 00:27:15.909653 | 2025-12-22 00:27:15.909797 | TASK [Run Zuul manifest role] 2025-12-22 00:27:15.931766 | localhost | ok 2025-12-22 00:27:15.950484 | 2025-12-22 00:27:15.950595 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-22 00:27:16.384541 | localhost | changed 2025-12-22 00:27:16.396788 | 2025-12-22 00:27:16.396933 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-22 00:27:16.445242 | localhost | ok 2025-12-22 00:27:16.466181 | 2025-12-22 00:27:16.466313 | TASK [Set zuul-log-path fact] 2025-12-22 00:27:16.490428 | localhost | ok 2025-12-22 00:27:16.511866 | 2025-12-22 00:27:16.511957 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-22 00:27:16.554711 | localhost | ok 2025-12-22 00:27:16.566958 | 2025-12-22 00:27:16.567044 | LOOP [Run upload-logs-swift role] 2025-12-22 00:27:16.615252 | localhost | Output suppressed because no_log was given 2025-12-22 00:27:16.651889 | 2025-12-22 00:27:16.652011 | TASK [Set zuul-log-path fact] 2025-12-22 00:27:16.687334 | localhost | skipping: Conditional result was False 2025-12-22 00:27:16.697051 | 2025-12-22 00:27:16.697272 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-22 00:27:17.129848 | localhost -> localhost | ok: Runtime: 0:00:00.006178 2025-12-22 00:27:17.136190 | 2025-12-22 00:27:17.136281 | TASK [upload-logs-swift : Upload logs to swift]