2025-12-07 00:20:49.380245 | Job console starting... 2025-12-07 00:20:49.388883 | Updating repositories 2025-12-07 00:20:49.506379 | Preparing job workspace 2025-12-07 00:20:53.437161 | Running Ansible setup... 2025-12-07 00:20:58.486589 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-07 00:20:59.100869 | 2025-12-07 00:20:59.101000 | PLAY [localhost] 2025-12-07 00:20:59.109507 | 2025-12-07 00:20:59.109578 | TASK [Gathering Facts] 2025-12-07 00:21:00.168320 | localhost | ok 2025-12-07 00:21:00.181979 | 2025-12-07 00:21:00.182146 | TASK [Setup log path fact] 2025-12-07 00:21:00.208508 | localhost | ok 2025-12-07 00:21:00.228786 | 2025-12-07 00:21:00.228965 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-07 00:21:00.258015 | localhost | ok 2025-12-07 00:21:00.266423 | 2025-12-07 00:21:00.266495 | TASK [emit-job-header : Print job information] 2025-12-07 00:21:00.307399 | # Job Information 2025-12-07 00:21:00.307568 | Ansible Version: 2.15.12 2025-12-07 00:21:00.307612 | Job: ansible-test-sanity-docker-milestone 2025-12-07 00:21:00.307642 | Pipeline: periodic 2025-12-07 00:21:00.307714 | Executor: ze04.softwarefactory-project.io 2025-12-07 00:21:00.307765 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-07 00:21:00.307810 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/368/ansible/368219c4e00f4ce5a29cdbe711ac41fb/ 2025-12-07 00:21:00.307846 | Event ID: dac9a6547cc040e1a4e62de5b8cc8f2b 2025-12-07 00:21:00.313557 | 2025-12-07 00:21:00.313648 | LOOP [emit-job-header : Print node information] 2025-12-07 00:21:00.442623 | localhost | ok: 2025-12-07 00:21:00.443171 | localhost | # Node Information 2025-12-07 00:21:00.443244 | localhost | Inventory Hostname: controller 2025-12-07 00:21:00.443290 | localhost | Hostname: np0005549263 2025-12-07 00:21:00.443335 | localhost | Username: zuul 2025-12-07 00:21:00.443381 | localhost | Distro: Fedora 37 2025-12-07 00:21:00.443421 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-07 00:21:00.443463 | localhost | Region: ca-ymq-1 2025-12-07 00:21:00.443517 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-07 00:21:00.443559 | localhost | Product Name: OpenStack Nova 2025-12-07 00:21:00.443599 | localhost | Interface IP: 162.253.55.49 2025-12-07 00:21:00.462808 | 2025-12-07 00:21:00.463147 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-07 00:21:00.896235 | localhost -> localhost | changed 2025-12-07 00:21:00.902355 | 2025-12-07 00:21:00.902429 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-07 00:21:01.841906 | localhost -> localhost | changed 2025-12-07 00:21:01.862661 | 2025-12-07 00:21:01.862871 | PLAY [all:!appliance*] 2025-12-07 00:21:01.879393 | 2025-12-07 00:21:01.879462 | TASK [include_role : start-zuul-console] 2025-12-07 00:21:01.903059 | controller | ok 2025-12-07 00:21:01.925441 | 2025-12-07 00:21:01.925576 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-07 00:21:02.333222 | controller | ok 2025-12-07 00:21:02.364674 | 2025-12-07 00:21:02.364866 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-07 00:21:24.831512 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-07 00:21:24.846471 | 2025-12-07 00:21:24.846641 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-07 00:21:25.394136 | controller | skipping: Conditional result was False 2025-12-07 00:21:25.411638 | 2025-12-07 00:21:25.411914 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-07 00:21:25.439751 | controller | skipping: Conditional result was False 2025-12-07 00:21:25.455526 | 2025-12-07 00:21:25.455673 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-07 00:21:25.483437 | controller | skipping: Conditional result was False 2025-12-07 00:21:25.496449 | 2025-12-07 00:21:25.496585 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-07 00:21:25.523855 | controller | skipping: Conditional result was False 2025-12-07 00:21:25.537727 | 2025-12-07 00:21:25.537874 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-07 00:21:25.565826 | controller | skipping: Conditional result was False 2025-12-07 00:21:25.578873 | 2025-12-07 00:21:25.579008 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-07 00:21:25.606078 | controller | skipping: Conditional result was False 2025-12-07 00:21:25.630142 | 2025-12-07 00:21:25.630273 | TASK [Disable Fedora Modular] 2025-12-07 00:21:25.898610 | controller | changed 2025-12-07 00:21:25.906656 | 2025-12-07 00:21:25.906770 | TASK [Enable EPEL] 2025-12-07 00:21:25.937284 | controller | skipping: Conditional result was False 2025-12-07 00:21:25.946100 | 2025-12-07 00:21:25.946279 | TASK [Register the RHEL node] 2025-12-07 00:21:26.503334 | 2025-12-07 00:21:26.503634 | TASK [Show the subscription-manager status] 2025-12-07 00:21:27.061537 | controller | skipping: Conditional result was False 2025-12-07 00:21:27.078446 | 2025-12-07 00:21:27.078614 | TASK [Enable EPEL on RHEL] 2025-12-07 00:21:27.660127 | controller | skipping: Conditional result was False 2025-12-07 00:21:27.674388 | 2025-12-07 00:21:27.674551 | TASK [Install git and tox] 2025-12-07 00:22:26.376641 | controller | changed 2025-12-07 00:22:26.390200 | 2025-12-07 00:22:26.390332 | TASK [include_role : prepare-workspace] 2025-12-07 00:22:26.431674 | controller | ok 2025-12-07 00:22:26.469215 | 2025-12-07 00:22:26.469320 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-07 00:22:26.725343 | controller | ok 2025-12-07 00:22:26.734375 | 2025-12-07 00:22:26.734464 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-07 00:22:38.677759 | controller | Output suppressed because no_log was given 2025-12-07 00:22:38.694940 | 2025-12-07 00:22:38.695109 | TASK [include_role : prepare-workspace-openshift] 2025-12-07 00:22:38.722615 | controller | skipping: Conditional result was False 2025-12-07 00:22:38.760660 | 2025-12-07 00:22:38.760804 | PLAY [all:!appliance] 2025-12-07 00:22:38.786788 | 2025-12-07 00:22:38.786942 | TASK [Run add-build-sshkey role (RSA)] 2025-12-07 00:22:38.823522 | controller | ok 2025-12-07 00:22:38.846233 | 2025-12-07 00:22:38.846360 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-07 00:22:39.115011 | controller -> localhost | ok 2025-12-07 00:22:39.122169 | 2025-12-07 00:22:39.122240 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-07 00:22:39.146166 | controller | ok 2025-12-07 00:22:39.161605 | controller | included: /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-07 00:22:39.167527 | 2025-12-07 00:22:39.167590 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-07 00:22:39.742177 | controller -> localhost | Generating public/private rsa key pair. 2025-12-07 00:22:39.742546 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/work/368219c4e00f4ce5a29cdbe711ac41fb_id_rsa. 2025-12-07 00:22:39.742610 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/work/368219c4e00f4ce5a29cdbe711ac41fb_id_rsa.pub. 2025-12-07 00:22:39.742656 | controller -> localhost | The key fingerprint is: 2025-12-07 00:22:39.742772 | controller -> localhost | SHA256:oGxx2h/C00DFeSNEYErugNBcAv/scliSFyx99jJVwIY zuul-build-sshkey 2025-12-07 00:22:39.742822 | controller -> localhost | The key's randomart image is: 2025-12-07 00:22:39.742864 | controller -> localhost | +---[RSA 2048]----+ 2025-12-07 00:22:39.742905 | controller -> localhost | |o+..o +O=o. | 2025-12-07 00:22:39.742947 | controller -> localhost | |.oo* +E *.o | 2025-12-07 00:22:39.742988 | controller -> localhost | |. + B *..o . | 2025-12-07 00:22:39.743029 | controller -> localhost | | O @ * | 2025-12-07 00:22:39.743068 | controller -> localhost | | o @ B S | 2025-12-07 00:22:39.743128 | controller -> localhost | | B * . | 2025-12-07 00:22:39.743178 | controller -> localhost | | o o . | 2025-12-07 00:22:39.743221 | controller -> localhost | | o | 2025-12-07 00:22:39.743262 | controller -> localhost | | | 2025-12-07 00:22:39.743307 | controller -> localhost | +----[SHA256]-----+ 2025-12-07 00:22:39.743392 | controller -> localhost | ok: Runtime: 0:00:00.150298 2025-12-07 00:22:39.757741 | 2025-12-07 00:22:39.757881 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-07 00:22:39.796845 | controller | ok 2025-12-07 00:22:39.818176 | controller | included: /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-07 00:22:39.832764 | 2025-12-07 00:22:39.832849 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-07 00:22:39.868175 | controller | skipping: Conditional result was False 2025-12-07 00:22:39.881520 | 2025-12-07 00:22:39.881654 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-07 00:22:40.372013 | controller | changed 2025-12-07 00:22:40.385582 | 2025-12-07 00:22:40.385770 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-07 00:22:40.620599 | controller | ok 2025-12-07 00:22:40.635493 | 2025-12-07 00:22:40.635639 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-07 00:22:41.256761 | controller | changed 2025-12-07 00:22:41.265277 | 2025-12-07 00:22:41.265376 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-07 00:22:41.901217 | controller | changed 2025-12-07 00:22:41.917113 | 2025-12-07 00:22:41.917283 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-07 00:22:41.954670 | controller | skipping: Conditional result was False 2025-12-07 00:22:42.010157 | 2025-12-07 00:22:42.010316 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-07 00:22:42.432663 | controller -> localhost | changed 2025-12-07 00:22:42.443888 | 2025-12-07 00:22:42.443954 | TASK [add-build-sshkey : Add back temp key] 2025-12-07 00:22:42.744733 | controller -> localhost | Identity added: /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/work/368219c4e00f4ce5a29cdbe711ac41fb_id_rsa (zuul-build-sshkey) 2025-12-07 00:22:42.745104 | controller -> localhost | ok: Runtime: 0:00:00.014681 2025-12-07 00:22:42.759920 | 2025-12-07 00:22:42.760097 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-07 00:22:43.069751 | controller | ok 2025-12-07 00:22:43.083762 | 2025-12-07 00:22:43.083937 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-07 00:22:43.122895 | controller | skipping: Conditional result was False 2025-12-07 00:22:43.151210 | 2025-12-07 00:22:43.151401 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-07 00:22:43.184758 | controller | ok 2025-12-07 00:22:43.208956 | 2025-12-07 00:22:43.209110 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-07 00:22:43.471148 | controller -> localhost | ok 2025-12-07 00:22:43.487315 | 2025-12-07 00:22:43.487517 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-07 00:22:43.528012 | controller | ok 2025-12-07 00:22:43.551512 | controller | included: /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-07 00:22:43.565601 | 2025-12-07 00:22:43.565805 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-07 00:22:43.869151 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-07 00:22:43.869398 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/work/368219c4e00f4ce5a29cdbe711ac41fb_id_ecdsa. 2025-12-07 00:22:43.869428 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/work/368219c4e00f4ce5a29cdbe711ac41fb_id_ecdsa.pub. 2025-12-07 00:22:43.869459 | controller -> localhost | The key fingerprint is: 2025-12-07 00:22:43.869480 | controller -> localhost | SHA256:yK8fS+0s8iXOChYxgvv/66GrqONIcOpciR2WHoYPSxc zuul-build-sshkey 2025-12-07 00:22:43.869501 | controller -> localhost | The key's randomart image is: 2025-12-07 00:22:43.869520 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-07 00:22:43.869537 | controller -> localhost | | | 2025-12-07 00:22:43.869555 | controller -> localhost | | . | 2025-12-07 00:22:43.869571 | controller -> localhost | |. .Eo | 2025-12-07 00:22:43.869588 | controller -> localhost | | ...o+ . | 2025-12-07 00:22:43.869605 | controller -> localhost | |o+.B. o S | 2025-12-07 00:22:43.869622 | controller -> localhost | |o+@ +. . . | 2025-12-07 00:22:43.869638 | controller -> localhost | |.+.*o . = o | 2025-12-07 00:22:43.869655 | controller -> localhost | |*..o o.*.B | 2025-12-07 00:22:43.869672 | controller -> localhost | |*=..++***.o | 2025-12-07 00:22:43.869813 | controller -> localhost | +----[SHA256]-----+ 2025-12-07 00:22:43.869879 | controller -> localhost | ok: Runtime: 0:00:00.014460 2025-12-07 00:22:43.878130 | 2025-12-07 00:22:43.878215 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-07 00:22:43.909429 | controller | ok 2025-12-07 00:22:43.917311 | controller | included: /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-07 00:22:43.926925 | 2025-12-07 00:22:43.927012 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-07 00:22:43.942407 | controller | skipping: Conditional result was False 2025-12-07 00:22:43.950981 | 2025-12-07 00:22:43.951088 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-07 00:22:44.227026 | controller | changed 2025-12-07 00:22:44.241802 | 2025-12-07 00:22:44.241963 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-07 00:22:44.491098 | controller | ok 2025-12-07 00:22:44.505860 | 2025-12-07 00:22:44.506011 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-07 00:22:45.177696 | controller | changed 2025-12-07 00:22:45.188592 | 2025-12-07 00:22:45.188731 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-07 00:22:45.845155 | controller | changed 2025-12-07 00:22:45.860260 | 2025-12-07 00:22:45.860435 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-07 00:22:45.899284 | controller | skipping: Conditional result was False 2025-12-07 00:22:45.918468 | 2025-12-07 00:22:45.918719 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-07 00:22:46.172562 | controller -> localhost | changed 2025-12-07 00:22:46.193905 | 2025-12-07 00:22:46.194059 | TASK [add-build-sshkey : Add back temp key] 2025-12-07 00:22:46.493548 | controller -> localhost | Identity added: /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/work/368219c4e00f4ce5a29cdbe711ac41fb_id_ecdsa (zuul-build-sshkey) 2025-12-07 00:22:46.493931 | controller -> localhost | ok: Runtime: 0:00:00.009622 2025-12-07 00:22:46.504423 | 2025-12-07 00:22:46.504543 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-07 00:22:46.708716 | controller | ok 2025-12-07 00:22:46.721970 | 2025-12-07 00:22:46.722114 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-07 00:22:46.750819 | controller | skipping: Conditional result was False 2025-12-07 00:22:46.784126 | 2025-12-07 00:22:46.784260 | TASK [include_role : remove-zuul-sshkey] 2025-12-07 00:22:46.810583 | controller | skipping: Conditional result was False 2025-12-07 00:22:46.822080 | 2025-12-07 00:22:46.822195 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-07 00:22:47.072218 | controller | ok: "logs" 2025-12-07 00:22:47.073046 | controller | ok: All items complete 2025-12-07 00:22:47.073125 | 2025-12-07 00:22:47.274516 | controller | ok: "artifacts" 2025-12-07 00:22:47.482397 | controller | ok: "docs" 2025-12-07 00:22:47.495608 | 2025-12-07 00:22:47.495764 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-07 00:22:47.721353 | controller | changed: "logs" 2025-12-07 00:22:47.913516 | controller | changed: "artifacts" 2025-12-07 00:22:48.103970 | controller | changed: "docs" 2025-12-07 00:22:48.135236 | 2025-12-07 00:22:48.135433 | PLAY RECAP 2025-12-07 00:22:48.135564 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-07 00:22:48.135603 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-07 00:22:48.135622 | 2025-12-07 00:22:48.269934 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-07 00:22:48.270849 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-07 00:22:48.833019 | 2025-12-07 00:22:48.833196 | PLAY [all] 2025-12-07 00:22:48.855942 | 2025-12-07 00:22:48.856133 | TASK [Install binary dependencies] 2025-12-07 00:22:48.926051 | controller | ok 2025-12-07 00:22:48.945720 | 2025-12-07 00:22:48.945856 | TASK [bindep : Include find tasks] 2025-12-07 00:22:48.975648 | controller | ok 2025-12-07 00:22:48.983541 | controller | included: /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-07 00:22:48.989985 | 2025-12-07 00:22:48.990057 | TASK [bindep : Look for bindep.txt] 2025-12-07 00:22:49.334353 | controller | ok 2025-12-07 00:22:49.348475 | 2025-12-07 00:22:49.348668 | TASK [bindep : Define bindep_file fact] 2025-12-07 00:22:49.377305 | controller | skipping: Conditional result was False 2025-12-07 00:22:49.392741 | 2025-12-07 00:22:49.392943 | TASK [bindep : Look for other-requirements.txt] 2025-12-07 00:22:49.618894 | controller | ok 2025-12-07 00:22:49.631497 | 2025-12-07 00:22:49.631664 | TASK [bindep : Define bindep_file fact] 2025-12-07 00:22:49.668981 | controller | skipping: Conditional result was False 2025-12-07 00:22:49.682943 | 2025-12-07 00:22:49.683133 | TASK [bindep : Look for bindep fallback file] 2025-12-07 00:22:49.720888 | controller | skipping: Conditional result was False 2025-12-07 00:22:49.738782 | 2025-12-07 00:22:49.738999 | TASK [bindep : Define bindep_file fact] 2025-12-07 00:22:49.776437 | controller | skipping: Conditional result was False 2025-12-07 00:22:49.786357 | 2025-12-07 00:22:49.786491 | TASK [bindep : Include bindep tasks] 2025-12-07 00:22:49.821362 | controller | skipping: Conditional result was False 2025-12-07 00:22:49.830967 | 2025-12-07 00:22:49.831090 | TASK [bindep : Include install tasks] 2025-12-07 00:22:49.855279 | controller | skipping: Conditional result was False 2025-12-07 00:22:49.864089 | 2025-12-07 00:22:49.864206 | LOOP [bindep : Include package tasks] 2025-12-07 00:22:49.935298 | 2025-12-07 00:22:49.935516 | TASK [Run test-setup role] 2025-12-07 00:22:49.960264 | controller | ok 2025-12-07 00:22:49.986007 | 2025-12-07 00:22:49.986132 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-07 00:22:50.195898 | controller | ok 2025-12-07 00:22:50.210000 | 2025-12-07 00:22:50.210149 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-07 00:22:50.756914 | controller | skipping: Conditional result was False 2025-12-07 00:22:50.812756 | 2025-12-07 00:22:50.812953 | PLAY RECAP 2025-12-07 00:22:50.813019 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-07 00:22:50.813049 | 2025-12-07 00:22:50.942571 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-07 00:22:50.944466 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-07 00:22:51.546218 | 2025-12-07 00:22:51.546339 | PLAY [controller] 2025-12-07 00:22:51.565830 | 2025-12-07 00:22:51.565916 | TASK [Create the /root directory] 2025-12-07 00:22:51.980532 | controller | ok 2025-12-07 00:22:51.992902 | 2025-12-07 00:22:51.993052 | TASK [Install glibc-langpack-en] 2025-12-07 00:22:55.913965 | controller | ok: Nothing to do 2025-12-07 00:22:55.920096 | 2025-12-07 00:22:55.920177 | TASK [Ensure controller directory exists] 2025-12-07 00:22:56.153788 | controller | changed 2025-12-07 00:22:56.167122 | 2025-12-07 00:22:56.167282 | TASK [Install container runtime] 2025-12-07 00:22:56.249296 | controller | ok 2025-12-07 00:22:56.308500 | 2025-12-07 00:22:56.308669 | LOOP [ensure-podman : Find distribution installation] 2025-12-07 00:22:56.349395 | controller | ok: "/var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-07 00:22:56.368860 | controller | included: /var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-07 00:22:56.379912 | 2025-12-07 00:22:56.380117 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-07 00:24:00.826315 | controller | changed 2025-12-07 00:24:00.845168 | 2025-12-07 00:24:00.845401 | TASK [ensure-podman : Fetch podman version] 2025-12-07 00:24:01.459341 | controller | Client: Podman Engine 2025-12-07 00:24:01.489703 | controller | Version: 4.6.2 2025-12-07 00:24:01.489770 | controller | API Version: 4.6.2 2025-12-07 00:24:01.489789 | controller | Go Version: go1.19.12 2025-12-07 00:24:01.489858 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-07 00:24:01.489882 | controller | OS/Arch: linux/amd64 2025-12-07 00:24:01.903825 | controller | ok: Runtime: 0:00:00.192069 2025-12-07 00:24:01.920774 | 2025-12-07 00:24:01.920953 | TASK [ensure-podman : Print podman version installed] 2025-12-07 00:24:01.961991 | Podman version: Client: Podman Engine 2025-12-07 00:24:01.962295 | Version: 4.6.2 2025-12-07 00:24:01.962356 | API Version: 4.6.2 2025-12-07 00:24:01.962400 | Go Version: go1.19.12 2025-12-07 00:24:01.962440 | Built: Mon Aug 28 19:38:31 2023 2025-12-07 00:24:01.962484 | OS/Arch: linux/amd64 2025-12-07 00:24:01.975513 | 2025-12-07 00:24:01.975661 | TASK [ensure-podman : Validate podman engine] 2025-12-07 00:24:02.523613 | controller | skipping: Conditional result was False 2025-12-07 00:24:02.538158 | 2025-12-07 00:24:02.538317 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-07 00:24:02.566437 | controller | skipping: Conditional result was False 2025-12-07 00:24:02.593565 | 2025-12-07 00:24:02.593802 | TASK [Ensure python3.8 is present] 2025-12-07 00:24:02.622573 | controller | skipping: Conditional result was False 2025-12-07 00:24:02.645359 | 2025-12-07 00:24:02.645741 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-07 00:24:02.677206 | controller | ok 2025-12-07 00:24:02.707922 | 2025-12-07 00:24:02.708138 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-07 00:24:04.078534 | controller | ok: Nothing to do 2025-12-07 00:24:04.093504 | 2025-12-07 00:24:04.093772 | TASK [our-ensure-python : Also install python3-devel] 2025-12-07 00:24:12.883843 | controller | changed 2025-12-07 00:24:12.914034 | 2025-12-07 00:24:12.914234 | TASK [Run ensure-virtualenv role] 2025-12-07 00:24:12.940237 | controller | ok 2025-12-07 00:24:13.003397 | 2025-12-07 00:24:13.003544 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-07 00:24:13.225276 | controller | /usr/bin/virtualenv 2025-12-07 00:24:13.538786 | controller | ok: Runtime: 0:00:00.004193 2025-12-07 00:24:13.554491 | 2025-12-07 00:24:13.554649 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-07 00:24:13.593193 | controller | skipping: Conditional result was False 2025-12-07 00:24:13.594048 | controller | ok: All items complete 2025-12-07 00:24:13.594138 | 2025-12-07 00:24:13.636437 | 2025-12-07 00:24:13.636650 | TASK [Find the full path of the Python interpreter] 2025-12-07 00:24:13.868043 | controller | /usr/bin/python3 2025-12-07 00:24:14.190268 | controller | ok 2025-12-07 00:24:14.203855 | 2025-12-07 00:24:14.204173 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-07 00:24:15.033549 | controller | created virtual environment CPython3.11.0.final.0-64 in 491ms 2025-12-07 00:24:15.050204 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-07 00:24:15.050241 | 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-07 00:24:15.050250 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-07 00:24:15.050265 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-07 00:24:15.265212 | controller | changed 2025-12-07 00:24:15.279876 | 2025-12-07 00:24:15.280024 | TASK [Set selinux package] 2025-12-07 00:24:15.320588 | controller | ok 2025-12-07 00:24:15.333102 | 2025-12-07 00:24:15.333256 | TASK [Set selinux package (Fedora)] 2025-12-07 00:24:15.371230 | controller | ok 2025-12-07 00:24:15.382360 | 2025-12-07 00:24:15.382498 | TASK [Install selinux into virtualenv] 2025-12-07 00:24:28.904027 | controller | Collecting selinux-please-lie-to-me 2025-12-07 00:24:41.167768 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-07 00:24:41.472647 | controller | Collecting setuptools<50.0.0 2025-12-07 00:24:41.478742 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-07 00:24:41.519207 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 22.0 MB/s eta 0:00:00 2025-12-07 00:24:41.599880 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-07 00:24:41.600145 | controller | Attempting uninstall: setuptools 2025-12-07 00:24:41.602497 | controller | Found existing installation: setuptools 62.6.0 2025-12-07 00:24:41.662356 | controller | Uninstalling setuptools-62.6.0: 2025-12-07 00:24:41.670100 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-07 00:24:42.016715 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-07 00:24:53.537572 | controller | 2025-12-07 00:24:53.615890 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-07 00:24:53.615931 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-07 00:24:53.960987 | controller | ok: Runtime: 0:00:38.015013 2025-12-07 00:24:53.974119 | 2025-12-07 00:24:53.974321 | TASK [Install pytest-forked into virtualenv] 2025-12-07 00:25:05.781462 | controller | Collecting pytest-forked 2025-12-07 00:25:18.027393 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-07 00:25:18.065934 | controller | Collecting py 2025-12-07 00:25:18.080490 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-07 00:25:18.099230 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 6.8 MB/s eta 0:00:00 2025-12-07 00:25:18.204394 | controller | Collecting pytest>=3.10 2025-12-07 00:25:18.209470 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-07 00:25:18.224104 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 31.2 MB/s eta 0:00:00 2025-12-07 00:25:18.262915 | controller | Collecting iniconfig>=1.0.1 2025-12-07 00:25:18.320098 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-07 00:25:18.365983 | controller | Collecting packaging>=22 2025-12-07 00:25:18.377236 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-07 00:25:18.386174 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 11.9 MB/s eta 0:00:00 2025-12-07 00:25:18.420724 | controller | Collecting pluggy<2,>=1.5 2025-12-07 00:25:18.424053 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-07 00:25:18.470765 | controller | Collecting pygments>=2.7.2 2025-12-07 00:25:18.474443 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-07 00:25:18.506881 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 50.7 MB/s eta 0:00:00 2025-12-07 00:25:18.575835 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-07 00:25:19.608108 | 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-07 00:25:19.616658 | controller | 2025-12-07 00:25:19.682393 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-07 00:25:19.682437 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-07 00:25:20.070760 | controller | ok: Runtime: 0:00:25.439390 2025-12-07 00:25:20.084533 | 2025-12-07 00:25:20.084672 | TASK [Update pip] 2025-12-07 00:25:20.602112 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-07 00:25:30.408869 | controller | Collecting pip 2025-12-07 00:25:42.731893 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-07 00:25:42.794422 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 31.1 MB/s eta 0:00:00 2025-12-07 00:25:42.859145 | controller | Installing collected packages: pip 2025-12-07 00:25:42.859368 | controller | Attempting uninstall: pip 2025-12-07 00:25:42.861697 | controller | Found existing installation: pip 22.2.2 2025-12-07 00:25:42.999069 | controller | Uninstalling pip-22.2.2: 2025-12-07 00:25:43.013943 | controller | Successfully uninstalled pip-22.2.2 2025-12-07 00:25:43.845227 | controller | Successfully installed pip-25.3 2025-12-07 00:25:44.148605 | controller | ok: Runtime: 0:00:23.615550 2025-12-07 00:25:44.161553 | 2025-12-07 00:25:44.161776 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-07 00:25:44.391239 | controller | changed 2025-12-07 00:25:44.398403 | 2025-12-07 00:25:44.398487 | TASK [Install ansible into virtualenv] 2025-12-07 00:25:44.915967 | controller | Processing ./src/github.com/ansible/ansible 2025-12-07 00:25:44.919241 | controller | Installing build dependencies: started 2025-12-07 00:26:07.668391 | controller | Installing build dependencies: finished with status 'done' 2025-12-07 00:26:07.669015 | controller | Getting requirements to build wheel: started 2025-12-07 00:26:08.394356 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-07 00:26:08.396006 | controller | Preparing metadata (pyproject.toml): started 2025-12-07 00:26:08.855468 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-07 00:26:08.860951 | 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-07 00:26:08.864695 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-07 00:26:08.970984 | controller | ERROR 2025-12-07 00:26:08.971270 | controller | { 2025-12-07 00:26:08.971333 | controller | "delta": "0:00:24.296370", 2025-12-07 00:26:08.971377 | controller | "end": "2025-12-07 00:26:08.928751", 2025-12-07 00:26:08.971446 | controller | "msg": "non-zero return code", 2025-12-07 00:26:08.971508 | controller | "rc": 1, 2025-12-07 00:26:08.971546 | controller | "start": "2025-12-07 00:25:44.632381" 2025-12-07 00:26:08.971581 | controller | } failure 2025-12-07 00:26:08.974457 | 2025-12-07 00:26:08.974565 | PLAY RECAP 2025-12-07 00:26:08.974653 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-07 00:26:08.974746 | 2025-12-07 00:26:09.102479 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-07 00:26:09.103495 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-07 00:26:09.698703 | 2025-12-07 00:26:09.698827 | PLAY [all] 2025-12-07 00:26:09.721181 | 2025-12-07 00:26:09.721318 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-07 00:26:10.008290 | controller | changed: non-zero return code 2025-12-07 00:26:10.021417 | 2025-12-07 00:26:10.021587 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-07 00:26:10.038653 | controller | skipping: Conditional result was False 2025-12-07 00:26:10.047180 | 2025-12-07 00:26:10.047276 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-07 00:26:10.078818 | 2025-12-07 00:26:10.079084 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-07 00:26:10.121327 | 2025-12-07 00:26:10.121637 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-07 00:26:10.149743 | controller | skipping: Conditional result was False 2025-12-07 00:26:10.167101 | 2025-12-07 00:26:10.167280 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-07 00:26:10.203820 | 2025-12-07 00:26:10.204053 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-07 00:26:10.238637 | controller | skipping: Conditional result was False 2025-12-07 00:26:10.247381 | 2025-12-07 00:26:10.247476 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-07 00:26:10.272524 | controller | skipping: Conditional result was False 2025-12-07 00:26:10.287927 | 2025-12-07 00:26:10.288266 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-07 00:26:10.316516 | controller | skipping: Conditional result was False 2025-12-07 00:26:10.370230 | 2025-12-07 00:26:10.370327 | PLAY RECAP 2025-12-07 00:26:10.370389 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-07 00:26:10.370417 | 2025-12-07 00:26:10.558407 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-07 00:26:10.560218 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-07 00:26:11.159874 | 2025-12-07 00:26:11.159983 | PLAY [all:!appliance*] 2025-12-07 00:26:11.181232 | 2025-12-07 00:26:11.181342 | TASK [unregister the node] 2025-12-07 00:26:11.711604 | controller | skipping: Conditional result was False 2025-12-07 00:26:11.719845 | 2025-12-07 00:26:11.719962 | TASK [include_role : fetch-output] 2025-12-07 00:26:11.752565 | controller | ok 2025-12-07 00:26:11.779162 | 2025-12-07 00:26:11.779340 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-07 00:26:11.846250 | controller | skipping: Conditional result was False 2025-12-07 00:26:11.860146 | 2025-12-07 00:26:11.860332 | TASK [fetch-output : Set log path for single node] 2025-12-07 00:26:11.912915 | controller | ok 2025-12-07 00:26:11.927058 | 2025-12-07 00:26:11.927231 | LOOP [fetch-output : Ensure local output dirs] 2025-12-07 00:26:12.353728 | controller -> localhost | ok: "/var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/work/logs" 2025-12-07 00:26:12.635003 | controller -> localhost | changed: "/var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/work/artifacts" 2025-12-07 00:26:12.893487 | controller -> localhost | changed: "/var/lib/zuul/builds/368219c4e00f4ce5a29cdbe711ac41fb/work/docs" 2025-12-07 00:26:12.907111 | 2025-12-07 00:26:12.907236 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-07 00:26:13.598037 | controller | changed: 2025-12-07 00:26:13.598283 | controller | .d..t...... ./ 2025-12-07 00:26:13.598329 | controller | cd+++++++++ controller/ 2025-12-07 00:26:13.598382 | controller | changed: All items complete 2025-12-07 00:26:13.598420 | 2025-12-07 00:26:14.114213 | controller | changed: .d..t...... ./ 2025-12-07 00:26:14.672770 | controller | changed: .d..t...... ./ 2025-12-07 00:26:14.706285 | 2025-12-07 00:26:14.706525 | TASK [include_role : fetch-output-openshift] 2025-12-07 00:26:14.732566 | controller | skipping: Conditional result was False 2025-12-07 00:26:14.742664 | 2025-12-07 00:26:14.742798 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-07 00:26:14.791786 | controller | skipping: Conditional result was False 2025-12-07 00:26:14.802299 | controller | skipping: Conditional result was False 2025-12-07 00:26:14.847779 | 2025-12-07 00:26:14.847948 | PLAY [localhost] 2025-12-07 00:26:14.864542 | 2025-12-07 00:26:14.864624 | TASK [Run Zuul manifest role] 2025-12-07 00:26:14.889347 | localhost | ok 2025-12-07 00:26:14.908015 | 2025-12-07 00:26:14.908106 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-07 00:26:15.323643 | localhost | changed 2025-12-07 00:26:15.328804 | 2025-12-07 00:26:15.328890 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-07 00:26:15.370316 | localhost | ok 2025-12-07 00:26:15.378295 | 2025-12-07 00:26:15.378353 | TASK [Set zuul-log-path fact] 2025-12-07 00:26:15.397950 | localhost | ok 2025-12-07 00:26:15.413003 | 2025-12-07 00:26:15.413068 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-07 00:26:15.444323 | localhost | ok 2025-12-07 00:26:15.452744 | 2025-12-07 00:26:15.452803 | LOOP [Run upload-logs-swift role] 2025-12-07 00:26:15.500910 | localhost | Output suppressed because no_log was given 2025-12-07 00:26:15.528176 | 2025-12-07 00:26:15.528246 | TASK [Set zuul-log-path fact] 2025-12-07 00:26:15.573746 | localhost | skipping: Conditional result was False 2025-12-07 00:26:15.580723 | 2025-12-07 00:26:15.580790 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-07 00:26:16.035643 | localhost -> localhost | ok: Runtime: 0:00:00.009495 2025-12-07 00:26:16.040735 | 2025-12-07 00:26:16.040801 | TASK [upload-logs-swift : Upload logs to swift]