2025-12-25 00:06:55.771434 | Job console starting... 2025-12-25 00:06:55.780448 | Updating repositories 2025-12-25 00:06:58.943780 | Preparing job workspace 2025-12-25 00:07:05.476129 | Running Ansible setup... 2025-12-25 00:07:09.882656 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-25 00:07:10.505060 | 2025-12-25 00:07:10.505219 | PLAY [localhost] 2025-12-25 00:07:10.513659 | 2025-12-25 00:07:10.513782 | TASK [Gathering Facts] 2025-12-25 00:07:11.563443 | localhost | ok 2025-12-25 00:07:11.591410 | 2025-12-25 00:07:11.591653 | TASK [Setup log path fact] 2025-12-25 00:07:11.611766 | localhost | ok 2025-12-25 00:07:11.625308 | 2025-12-25 00:07:11.625379 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-25 00:07:11.653291 | localhost | ok 2025-12-25 00:07:11.666269 | 2025-12-25 00:07:11.666499 | TASK [emit-job-header : Print job information] 2025-12-25 00:07:11.713783 | # Job Information 2025-12-25 00:07:11.714058 | Ansible Version: 2.15.12 2025-12-25 00:07:11.714119 | Job: ansible-test-sanity-docker-devel 2025-12-25 00:07:11.714384 | Pipeline: periodic 2025-12-25 00:07:11.714447 | Executor: ze04.softwarefactory-project.io 2025-12-25 00:07:11.714488 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-12-25 00:07:11.714530 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/43d/ansible/43d69bd48e0648daa7e794e013a6f6c9/ 2025-12-25 00:07:11.714568 | Event ID: 9bcd164eed0a4284892079c0f800abca 2025-12-25 00:07:11.721913 | 2025-12-25 00:07:11.722594 | LOOP [emit-job-header : Print node information] 2025-12-25 00:07:11.843235 | localhost | ok: 2025-12-25 00:07:11.843428 | localhost | # Node Information 2025-12-25 00:07:11.843456 | localhost | Inventory Hostname: controller 2025-12-25 00:07:11.843478 | localhost | Hostname: np0005570303 2025-12-25 00:07:11.843499 | localhost | Username: zuul 2025-12-25 00:07:11.843524 | localhost | Distro: Fedora 37 2025-12-25 00:07:11.843544 | localhost | Provider: ansible-vexxhost-ca-ymq-1 2025-12-25 00:07:11.843563 | localhost | Region: ca-ymq-1 2025-12-25 00:07:11.843582 | localhost | Label: ansible-fedora-37-1vcpu 2025-12-25 00:07:11.843601 | localhost | Product Name: OpenStack Nova 2025-12-25 00:07:11.843619 | localhost | Interface IP: 162.253.55.42 2025-12-25 00:07:11.856800 | 2025-12-25 00:07:11.856919 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-12-25 00:07:12.287358 | localhost -> localhost | changed 2025-12-25 00:07:12.300211 | 2025-12-25 00:07:12.300373 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-12-25 00:07:13.375862 | localhost -> localhost | changed 2025-12-25 00:07:13.412124 | 2025-12-25 00:07:13.412247 | PLAY [all:!appliance*] 2025-12-25 00:07:13.442575 | 2025-12-25 00:07:13.442734 | TASK [include_role : start-zuul-console] 2025-12-25 00:07:13.463952 | controller | ok 2025-12-25 00:07:13.483836 | 2025-12-25 00:07:13.483961 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-12-25 00:07:13.895119 | controller | ok 2025-12-25 00:07:13.941541 | 2025-12-25 00:07:13.941717 | TASK [use-our-mirror : Retrieve the IP address] 2025-12-25 00:07:36.504241 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-12-25 00:07:36.523406 | 2025-12-25 00:07:36.523546 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-12-25 00:07:37.071571 | controller | skipping: Conditional result was False 2025-12-25 00:07:37.083775 | 2025-12-25 00:07:37.083921 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-12-25 00:07:37.099185 | controller | skipping: Conditional result was False 2025-12-25 00:07:37.114690 | 2025-12-25 00:07:37.114813 | TASK [use-our-mirror : Create the podman configuration directory] 2025-12-25 00:07:37.138897 | controller | skipping: Conditional result was False 2025-12-25 00:07:37.145490 | 2025-12-25 00:07:37.145578 | TASK [use-our-mirror : Copy the podman configuration] 2025-12-25 00:07:37.172978 | controller | skipping: Conditional result was False 2025-12-25 00:07:37.182882 | 2025-12-25 00:07:37.182973 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-12-25 00:07:37.208697 | controller | skipping: Conditional result was False 2025-12-25 00:07:37.218299 | 2025-12-25 00:07:37.218398 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-12-25 00:07:37.245401 | controller | skipping: Conditional result was False 2025-12-25 00:07:37.269948 | 2025-12-25 00:07:37.270071 | TASK [Disable Fedora Modular] 2025-12-25 00:07:37.633577 | controller | changed 2025-12-25 00:07:37.652584 | 2025-12-25 00:07:37.652761 | TASK [Enable EPEL] 2025-12-25 00:07:37.678162 | controller | skipping: Conditional result was False 2025-12-25 00:07:37.684851 | 2025-12-25 00:07:37.684975 | TASK [Register the RHEL node] 2025-12-25 00:07:38.234666 | 2025-12-25 00:07:38.234996 | TASK [Show the subscription-manager status] 2025-12-25 00:07:38.799146 | controller | skipping: Conditional result was False 2025-12-25 00:07:38.809488 | 2025-12-25 00:07:38.809643 | TASK [Enable EPEL on RHEL] 2025-12-25 00:07:39.367547 | controller | skipping: Conditional result was False 2025-12-25 00:07:39.383877 | 2025-12-25 00:07:39.384009 | TASK [Install git and tox] 2025-12-25 00:09:06.264457 | controller | changed 2025-12-25 00:09:06.274505 | 2025-12-25 00:09:06.274668 | TASK [include_role : prepare-workspace] 2025-12-25 00:09:06.305228 | controller | ok 2025-12-25 00:09:06.337998 | 2025-12-25 00:09:06.338193 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-12-25 00:09:06.604008 | controller | ok 2025-12-25 00:09:06.620259 | 2025-12-25 00:09:06.620408 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-12-25 00:09:19.368812 | controller | Output suppressed because no_log was given 2025-12-25 00:09:19.380631 | 2025-12-25 00:09:19.380737 | TASK [include_role : prepare-workspace-openshift] 2025-12-25 00:09:19.407329 | controller | skipping: Conditional result was False 2025-12-25 00:09:19.434527 | 2025-12-25 00:09:19.434631 | PLAY [all:!appliance] 2025-12-25 00:09:19.453045 | 2025-12-25 00:09:19.453142 | TASK [Run add-build-sshkey role (RSA)] 2025-12-25 00:09:19.483489 | controller | ok 2025-12-25 00:09:19.500306 | 2025-12-25 00:09:19.500414 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-25 00:09:19.751278 | controller -> localhost | ok 2025-12-25 00:09:19.806444 | 2025-12-25 00:09:19.806593 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-25 00:09:19.852174 | controller | ok 2025-12-25 00:09:19.874187 | controller | included: /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-25 00:09:19.884478 | 2025-12-25 00:09:19.884606 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-25 00:09:20.368127 | controller -> localhost | Generating public/private rsa key pair. 2025-12-25 00:09:20.368568 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/work/43d69bd48e0648daa7e794e013a6f6c9_id_rsa. 2025-12-25 00:09:20.368637 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/work/43d69bd48e0648daa7e794e013a6f6c9_id_rsa.pub. 2025-12-25 00:09:20.368724 | controller -> localhost | The key fingerprint is: 2025-12-25 00:09:20.368781 | controller -> localhost | SHA256:8rsesXh8DqU/yVWa8IODkmoHC2SCMArh2/sSGLS6wE8 zuul-build-sshkey 2025-12-25 00:09:20.368826 | controller -> localhost | The key's randomart image is: 2025-12-25 00:09:20.368898 | controller -> localhost | +---[RSA 2048]----+ 2025-12-25 00:09:20.368944 | controller -> localhost | |.. | 2025-12-25 00:09:20.368988 | controller -> localhost | |=. | 2025-12-25 00:09:20.369030 | controller -> localhost | |*o. | 2025-12-25 00:09:20.369100 | controller -> localhost | |+o= . . | 2025-12-25 00:09:20.369144 | controller -> localhost | |o=o. ..S..+ + | 2025-12-25 00:09:20.369201 | controller -> localhost | |oo.Eo o=.=o * | 2025-12-25 00:09:20.369252 | controller -> localhost | |..oo.+..O..+ . | 2025-12-25 00:09:20.369298 | controller -> localhost | |. o= .. B+ | 2025-12-25 00:09:20.369342 | controller -> localhost | | ..o .+.o. | 2025-12-25 00:09:20.369392 | controller -> localhost | +----[SHA256]-----+ 2025-12-25 00:09:20.369741 | controller -> localhost | ok: Runtime: 0:00:00.095674 2025-12-25 00:09:20.386357 | 2025-12-25 00:09:20.386516 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-25 00:09:20.421661 | controller | ok 2025-12-25 00:09:20.439292 | controller | included: /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-25 00:09:20.453586 | 2025-12-25 00:09:20.453700 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-25 00:09:20.479325 | controller | skipping: Conditional result was False 2025-12-25 00:09:20.494724 | 2025-12-25 00:09:20.494862 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-25 00:09:20.909796 | controller | changed 2025-12-25 00:09:20.925298 | 2025-12-25 00:09:20.925444 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-25 00:09:21.172235 | controller | ok 2025-12-25 00:09:21.188540 | 2025-12-25 00:09:21.188791 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-25 00:09:21.843197 | controller | changed 2025-12-25 00:09:21.861006 | 2025-12-25 00:09:21.861222 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-25 00:09:22.476437 | controller | changed 2025-12-25 00:09:22.482549 | 2025-12-25 00:09:22.482622 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-25 00:09:22.507308 | controller | skipping: Conditional result was False 2025-12-25 00:09:22.514538 | 2025-12-25 00:09:22.514624 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-25 00:09:22.865559 | controller -> localhost | changed 2025-12-25 00:09:22.879906 | 2025-12-25 00:09:22.879999 | TASK [add-build-sshkey : Add back temp key] 2025-12-25 00:09:23.211771 | controller -> localhost | Identity added: /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/work/43d69bd48e0648daa7e794e013a6f6c9_id_rsa (zuul-build-sshkey) 2025-12-25 00:09:23.212040 | controller -> localhost | ok: Runtime: 0:00:00.014281 2025-12-25 00:09:23.219883 | 2025-12-25 00:09:23.219973 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-25 00:09:23.562903 | controller | ok 2025-12-25 00:09:23.579427 | 2025-12-25 00:09:23.579667 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-25 00:09:23.616141 | controller | skipping: Conditional result was False 2025-12-25 00:09:23.630921 | 2025-12-25 00:09:23.631029 | TASK [Run add-build-sshkey role (ECDSA)] 2025-12-25 00:09:23.652270 | controller | ok 2025-12-25 00:09:23.671017 | 2025-12-25 00:09:23.671100 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-12-25 00:09:23.974037 | controller -> localhost | ok 2025-12-25 00:09:23.989247 | 2025-12-25 00:09:23.989421 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-12-25 00:09:24.046598 | controller | ok 2025-12-25 00:09:24.066614 | controller | included: /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-12-25 00:09:24.077017 | 2025-12-25 00:09:24.077141 | TASK [add-build-sshkey : Create Temp SSH key] 2025-12-25 00:09:24.379465 | controller -> localhost | Generating public/private ecdsa key pair. 2025-12-25 00:09:24.379648 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/work/43d69bd48e0648daa7e794e013a6f6c9_id_ecdsa. 2025-12-25 00:09:24.379695 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/work/43d69bd48e0648daa7e794e013a6f6c9_id_ecdsa.pub. 2025-12-25 00:09:24.379730 | controller -> localhost | The key fingerprint is: 2025-12-25 00:09:24.379752 | controller -> localhost | SHA256:9QK+UQEn+ZFxFbrL1T9WJjqh3Ek0TZfDAWUIl786ggE zuul-build-sshkey 2025-12-25 00:09:24.379771 | controller -> localhost | The key's randomart image is: 2025-12-25 00:09:24.379790 | controller -> localhost | +---[ECDSA 521]---+ 2025-12-25 00:09:24.379809 | controller -> localhost | | oo++o+X=+| 2025-12-25 00:09:24.379827 | controller -> localhost | | .ooo.*.= | 2025-12-25 00:09:24.379844 | controller -> localhost | | ..o.+ o .| 2025-12-25 00:09:24.379861 | controller -> localhost | | E +.o o o | 2025-12-25 00:09:24.379878 | controller -> localhost | | S . = o =| 2025-12-25 00:09:24.379896 | controller -> localhost | | = * * +o| 2025-12-25 00:09:24.379913 | controller -> localhost | | . = B .o.| 2025-12-25 00:09:24.379930 | controller -> localhost | | . . +. .| 2025-12-25 00:09:24.379947 | controller -> localhost | | . . | 2025-12-25 00:09:24.379964 | controller -> localhost | +----[SHA256]-----+ 2025-12-25 00:09:24.380014 | controller -> localhost | ok: Runtime: 0:00:00.008466 2025-12-25 00:09:24.387130 | 2025-12-25 00:09:24.387206 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-12-25 00:09:24.417368 | controller | ok 2025-12-25 00:09:24.426334 | controller | included: /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-12-25 00:09:24.436300 | 2025-12-25 00:09:24.436386 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-12-25 00:09:24.451399 | controller | skipping: Conditional result was False 2025-12-25 00:09:24.458553 | 2025-12-25 00:09:24.458659 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-12-25 00:09:24.776038 | controller | changed 2025-12-25 00:09:24.790822 | 2025-12-25 00:09:24.790998 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-12-25 00:09:25.046107 | controller | ok 2025-12-25 00:09:25.055629 | 2025-12-25 00:09:25.055760 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-12-25 00:09:25.726729 | controller | changed 2025-12-25 00:09:25.736413 | 2025-12-25 00:09:25.736558 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-12-25 00:09:26.432829 | controller | changed 2025-12-25 00:09:26.441779 | 2025-12-25 00:09:26.441867 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-12-25 00:09:26.477130 | controller | skipping: Conditional result was False 2025-12-25 00:09:26.486614 | 2025-12-25 00:09:26.486733 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-12-25 00:09:26.776002 | controller -> localhost | changed 2025-12-25 00:09:26.788344 | 2025-12-25 00:09:26.788477 | TASK [add-build-sshkey : Add back temp key] 2025-12-25 00:09:27.069389 | controller -> localhost | Identity added: /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/work/43d69bd48e0648daa7e794e013a6f6c9_id_ecdsa (zuul-build-sshkey) 2025-12-25 00:09:27.069633 | controller -> localhost | ok: Runtime: 0:00:00.012397 2025-12-25 00:09:27.078479 | 2025-12-25 00:09:27.078570 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-12-25 00:09:27.337085 | controller | ok 2025-12-25 00:09:27.351917 | 2025-12-25 00:09:27.352122 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-12-25 00:09:27.380611 | controller | skipping: Conditional result was False 2025-12-25 00:09:27.393728 | 2025-12-25 00:09:27.393826 | TASK [include_role : remove-zuul-sshkey] 2025-12-25 00:09:27.418686 | controller | skipping: Conditional result was False 2025-12-25 00:09:27.425740 | 2025-12-25 00:09:27.425826 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-12-25 00:09:27.756475 | controller | ok: "logs" 2025-12-25 00:09:27.756734 | controller | ok: All items complete 2025-12-25 00:09:27.756778 | 2025-12-25 00:09:27.907183 | controller | ok: "artifacts" 2025-12-25 00:09:28.120647 | controller | ok: "docs" 2025-12-25 00:09:28.143148 | 2025-12-25 00:09:28.143357 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-12-25 00:09:28.401243 | controller | changed: "logs" 2025-12-25 00:09:28.623725 | controller | changed: "artifacts" 2025-12-25 00:09:28.844531 | controller | changed: "docs" 2025-12-25 00:09:28.885695 | 2025-12-25 00:09:28.885821 | PLAY RECAP 2025-12-25 00:09:28.885881 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-12-25 00:09:28.885912 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-12-25 00:09:28.885930 | 2025-12-25 00:09:29.071222 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-12-25 00:09:29.072394 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-25 00:09:29.660363 | 2025-12-25 00:09:29.660481 | PLAY [all] 2025-12-25 00:09:29.684639 | 2025-12-25 00:09:29.684766 | TASK [Install binary dependencies] 2025-12-25 00:09:29.744534 | controller | ok 2025-12-25 00:09:29.764488 | 2025-12-25 00:09:29.764571 | TASK [bindep : Include find tasks] 2025-12-25 00:09:29.804777 | controller | ok 2025-12-25 00:09:29.813302 | controller | included: /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-12-25 00:09:29.820155 | 2025-12-25 00:09:29.820225 | TASK [bindep : Look for bindep.txt] 2025-12-25 00:09:30.197244 | controller | ok 2025-12-25 00:09:30.210996 | 2025-12-25 00:09:30.211146 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:09:30.240510 | controller | skipping: Conditional result was False 2025-12-25 00:09:30.254878 | 2025-12-25 00:09:30.255024 | TASK [bindep : Look for other-requirements.txt] 2025-12-25 00:09:30.489784 | controller | ok 2025-12-25 00:09:30.504511 | 2025-12-25 00:09:30.504732 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:09:30.543024 | controller | skipping: Conditional result was False 2025-12-25 00:09:30.561053 | 2025-12-25 00:09:30.561306 | TASK [bindep : Look for bindep fallback file] 2025-12-25 00:09:30.609607 | controller | skipping: Conditional result was False 2025-12-25 00:09:30.618602 | 2025-12-25 00:09:30.618766 | TASK [bindep : Define bindep_file fact] 2025-12-25 00:09:30.645333 | controller | skipping: Conditional result was False 2025-12-25 00:09:30.655534 | 2025-12-25 00:09:30.655656 | TASK [bindep : Include bindep tasks] 2025-12-25 00:09:30.691293 | controller | skipping: Conditional result was False 2025-12-25 00:09:30.700949 | 2025-12-25 00:09:30.701056 | TASK [bindep : Include install tasks] 2025-12-25 00:09:30.726503 | controller | skipping: Conditional result was False 2025-12-25 00:09:30.735368 | 2025-12-25 00:09:30.735478 | LOOP [bindep : Include package tasks] 2025-12-25 00:09:30.818635 | 2025-12-25 00:09:30.819033 | TASK [Run test-setup role] 2025-12-25 00:09:30.845397 | controller | ok 2025-12-25 00:09:30.870277 | 2025-12-25 00:09:30.870403 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-12-25 00:09:31.104567 | controller | ok 2025-12-25 00:09:31.119664 | 2025-12-25 00:09:31.119880 | TASK [test-setup : Run tools/test-setup.sh] 2025-12-25 00:09:31.680358 | controller | skipping: Conditional result was False 2025-12-25 00:09:31.715903 | 2025-12-25 00:09:31.716018 | PLAY RECAP 2025-12-25 00:09:31.716058 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-25 00:09:31.716078 | 2025-12-25 00:09:31.829929 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-12-25 00:09:31.830993 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-25 00:09:32.441979 | 2025-12-25 00:09:32.442144 | PLAY [controller] 2025-12-25 00:09:32.464668 | 2025-12-25 00:09:32.464812 | TASK [Create the /root directory] 2025-12-25 00:09:32.920012 | controller | ok 2025-12-25 00:09:32.930016 | 2025-12-25 00:09:32.930170 | TASK [Install glibc-langpack-en] 2025-12-25 00:09:37.333816 | controller | ok: Nothing to do 2025-12-25 00:09:37.347108 | 2025-12-25 00:09:37.347287 | TASK [Ensure controller directory exists] 2025-12-25 00:09:37.597628 | controller | changed 2025-12-25 00:09:37.606137 | 2025-12-25 00:09:37.606236 | TASK [Install container runtime] 2025-12-25 00:09:37.665287 | controller | ok 2025-12-25 00:09:37.724972 | 2025-12-25 00:09:37.725226 | LOOP [ensure-podman : Find distribution installation] 2025-12-25 00:09:37.748886 | controller | ok: "/var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-12-25 00:09:37.756754 | controller | included: /var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-12-25 00:09:37.763147 | 2025-12-25 00:09:37.763215 | TASK [ensure-podman : Install podman (RedHat)] 2025-12-25 00:10:47.121930 | controller | changed 2025-12-25 00:10:47.131990 | 2025-12-25 00:10:47.132097 | TASK [ensure-podman : Fetch podman version] 2025-12-25 00:10:47.702577 | controller | Client: Podman Engine 2025-12-25 00:10:47.702650 | controller | Version: 4.6.2 2025-12-25 00:10:47.702682 | controller | API Version: 4.6.2 2025-12-25 00:10:47.702712 | controller | Go Version: go1.19.12 2025-12-25 00:10:47.702751 | controller | Built: Mon Aug 28 19:38:31 2023 2025-12-25 00:10:47.702801 | controller | OS/Arch: linux/amd64 2025-12-25 00:10:48.178655 | controller | ok: Runtime: 0:00:00.193650 2025-12-25 00:10:48.185714 | 2025-12-25 00:10:48.185800 | TASK [ensure-podman : Print podman version installed] 2025-12-25 00:10:48.234404 | Podman version: Client: Podman Engine 2025-12-25 00:10:48.234664 | Version: 4.6.2 2025-12-25 00:10:48.234787 | API Version: 4.6.2 2025-12-25 00:10:48.234835 | Go Version: go1.19.12 2025-12-25 00:10:48.234875 | Built: Mon Aug 28 19:38:31 2023 2025-12-25 00:10:48.234917 | OS/Arch: linux/amd64 2025-12-25 00:10:48.250544 | 2025-12-25 00:10:48.250762 | TASK [ensure-podman : Validate podman engine] 2025-12-25 00:10:48.801388 | controller | skipping: Conditional result was False 2025-12-25 00:10:48.815896 | 2025-12-25 00:10:48.816039 | TASK [ensure-podman : Set up docker compatability socket] 2025-12-25 00:10:48.833230 | controller | skipping: Conditional result was False 2025-12-25 00:10:48.858063 | 2025-12-25 00:10:48.858324 | TASK [Ensure python3.8 is present] 2025-12-25 00:10:48.875002 | controller | skipping: Conditional result was False 2025-12-25 00:10:48.890576 | 2025-12-25 00:10:48.890769 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-12-25 00:10:48.915495 | controller | ok 2025-12-25 00:10:48.941074 | 2025-12-25 00:10:48.941170 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-12-25 00:10:50.305407 | controller | ok: Nothing to do 2025-12-25 00:10:50.321196 | 2025-12-25 00:10:50.321477 | TASK [our-ensure-python : Also install python3-devel] 2025-12-25 00:10:59.233121 | controller | changed 2025-12-25 00:10:59.251001 | 2025-12-25 00:10:59.251144 | TASK [Run ensure-virtualenv role] 2025-12-25 00:10:59.276057 | controller | ok 2025-12-25 00:10:59.307518 | 2025-12-25 00:10:59.307640 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-12-25 00:10:59.551905 | controller | /usr/bin/virtualenv 2025-12-25 00:10:59.874467 | controller | ok: Runtime: 0:00:00.005258 2025-12-25 00:10:59.881260 | 2025-12-25 00:10:59.881365 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-12-25 00:10:59.909587 | controller | skipping: Conditional result was False 2025-12-25 00:10:59.909847 | controller | ok: All items complete 2025-12-25 00:10:59.909876 | 2025-12-25 00:10:59.939038 | 2025-12-25 00:10:59.939228 | TASK [Find the full path of the Python interpreter] 2025-12-25 00:11:00.174858 | controller | /usr/bin/python3 2025-12-25 00:11:00.486935 | controller | ok 2025-12-25 00:11:00.502527 | 2025-12-25 00:11:00.502725 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-12-25 00:11:01.280751 | controller | created virtual environment CPython3.11.0.final.0-64 in 454ms 2025-12-25 00:11:01.296207 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-12-25 00:11:01.296245 | 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-25 00:11:01.296254 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-12-25 00:11:01.296268 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-12-25 00:11:01.566279 | controller | changed 2025-12-25 00:11:01.573587 | 2025-12-25 00:11:01.573664 | TASK [Set selinux package] 2025-12-25 00:11:01.604577 | controller | ok 2025-12-25 00:11:01.610710 | 2025-12-25 00:11:01.610782 | TASK [Set selinux package (Fedora)] 2025-12-25 00:11:01.653386 | controller | ok 2025-12-25 00:11:01.658710 | 2025-12-25 00:11:01.658778 | TASK [Install selinux into virtualenv] 2025-12-25 00:11:27.119195 | controller | Collecting selinux-please-lie-to-me 2025-12-25 00:11:39.374790 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-12-25 00:11:39.679320 | controller | Collecting setuptools<50.0.0 2025-12-25 00:11:39.684704 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-12-25 00:11:39.771815 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 9.6 MB/s eta 0:00:00 2025-12-25 00:11:39.854229 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-12-25 00:11:39.854438 | controller | Attempting uninstall: setuptools 2025-12-25 00:11:39.856862 | controller | Found existing installation: setuptools 62.6.0 2025-12-25 00:11:39.917270 | controller | Uninstalling setuptools-62.6.0: 2025-12-25 00:11:39.926148 | controller | Successfully uninstalled setuptools-62.6.0 2025-12-25 00:11:40.301555 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-12-25 00:11:51.751354 | controller | 2025-12-25 00:11:51.834342 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-25 00:11:51.834387 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-25 00:11:52.220040 | controller | ok: Runtime: 0:00:49.957278 2025-12-25 00:11:52.226121 | 2025-12-25 00:11:52.226187 | TASK [Install pytest-forked into virtualenv] 2025-12-25 00:12:04.023734 | controller | Collecting pytest-forked 2025-12-25 00:12:28.210844 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-12-25 00:12:28.252102 | controller | Collecting py 2025-12-25 00:12:28.255302 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-12-25 00:12:28.282031 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.8 MB/s eta 0:00:00 2025-12-25 00:12:28.393281 | controller | Collecting pytest>=3.10 2025-12-25 00:12:28.397342 | controller | Downloading pytest-9.0.2-py3-none-any.whl (374 kB) 2025-12-25 00:12:28.415013 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 374.8/374.8 kB 24.8 MB/s eta 0:00:00 2025-12-25 00:12:28.453324 | controller | Collecting iniconfig>=1.0.1 2025-12-25 00:12:28.456748 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-12-25 00:12:28.498713 | controller | Collecting packaging>=22 2025-12-25 00:12:28.501933 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-12-25 00:12:28.510833 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 11.3 MB/s eta 0:00:00 2025-12-25 00:12:28.547697 | controller | Collecting pluggy<2,>=1.5 2025-12-25 00:12:28.551107 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-12-25 00:12:28.601716 | controller | Collecting pygments>=2.7.2 2025-12-25 00:12:28.605505 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-12-25 00:12:28.633744 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 47.4 MB/s eta 0:00:00 2025-12-25 00:12:28.703622 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-12-25 00:12:29.757621 | 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-25 00:12:29.766548 | controller | 2025-12-25 00:12:29.846645 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-12-25 00:12:29.846686 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-12-25 00:12:30.290264 | controller | ok: Runtime: 0:00:37.408206 2025-12-25 00:12:30.305318 | 2025-12-25 00:12:30.305579 | TASK [Update pip] 2025-12-25 00:12:30.858617 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-12-25 00:12:40.605979 | controller | Collecting pip 2025-12-25 00:13:04.718344 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-12-25 00:13:04.780093 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 31.5 MB/s eta 0:00:00 2025-12-25 00:13:04.843356 | controller | Installing collected packages: pip 2025-12-25 00:13:04.843511 | controller | Attempting uninstall: pip 2025-12-25 00:13:04.845711 | controller | Found existing installation: pip 22.2.2 2025-12-25 00:13:04.985993 | controller | Uninstalling pip-22.2.2: 2025-12-25 00:13:05.002226 | controller | Successfully uninstalled pip-22.2.2 2025-12-25 00:13:05.800982 | controller | Successfully installed pip-25.3 2025-12-25 00:13:05.906215 | controller | ok: Runtime: 0:00:35.327883 2025-12-25 00:13:05.912522 | 2025-12-25 00:13:05.912875 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-12-25 00:13:06.138427 | controller | changed 2025-12-25 00:13:06.190002 | 2025-12-25 00:13:06.190168 | TASK [Install ansible into virtualenv] 2025-12-25 00:13:06.703592 | controller | Processing ./src/github.com/ansible/ansible 2025-12-25 00:13:06.706772 | controller | Installing build dependencies: started 2025-12-25 00:13:31.961854 | controller | Installing build dependencies: finished with status 'done' 2025-12-25 00:13:31.962874 | controller | Getting requirements to build wheel: started 2025-12-25 00:13:32.698014 | controller | Getting requirements to build wheel: finished with status 'done' 2025-12-25 00:13:32.699482 | controller | Preparing metadata (pyproject.toml): started 2025-12-25 00:13:33.164597 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-12-25 00:13:33.169315 | 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-25 00:13:33.172887 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-12-25 00:13:33.272577 | controller | ERROR 2025-12-25 00:13:33.273010 | controller | { 2025-12-25 00:13:33.273077 | controller | "delta": "0:00:26.809461", 2025-12-25 00:13:33.273123 | controller | "end": "2025-12-25 00:13:33.235672", 2025-12-25 00:13:33.273165 | controller | "msg": "non-zero return code", 2025-12-25 00:13:33.273223 | controller | "rc": 1, 2025-12-25 00:13:33.273265 | controller | "start": "2025-12-25 00:13:06.426211" 2025-12-25 00:13:33.273304 | controller | } failure 2025-12-25 00:13:33.276326 | 2025-12-25 00:13:33.276433 | PLAY RECAP 2025-12-25 00:13:33.276529 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-12-25 00:13:33.276573 | 2025-12-25 00:13:33.481588 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-12-25 00:13:33.484012 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-25 00:13:34.159365 | 2025-12-25 00:13:34.159494 | PLAY [all] 2025-12-25 00:13:34.181829 | 2025-12-25 00:13:34.181964 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-12-25 00:13:34.475777 | controller | changed: non-zero return code 2025-12-25 00:13:34.488708 | 2025-12-25 00:13:34.488884 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-12-25 00:13:34.516570 | controller | skipping: Conditional result was False 2025-12-25 00:13:34.525267 | 2025-12-25 00:13:34.525376 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-12-25 00:13:34.560893 | 2025-12-25 00:13:34.561108 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-12-25 00:13:34.594893 | 2025-12-25 00:13:34.595097 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-12-25 00:13:34.621005 | controller | skipping: Conditional result was False 2025-12-25 00:13:34.638353 | 2025-12-25 00:13:34.638606 | LOOP [fetch-subunit-output : Generate subunit file] 2025-12-25 00:13:34.675191 | 2025-12-25 00:13:34.675413 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-12-25 00:13:34.701579 | controller | skipping: Conditional result was False 2025-12-25 00:13:34.713967 | 2025-12-25 00:13:34.714134 | TASK [fetch-subunit-output : Remove the temporary file] 2025-12-25 00:13:34.739932 | controller | skipping: Conditional result was False 2025-12-25 00:13:34.750588 | 2025-12-25 00:13:34.750792 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-12-25 00:13:34.776782 | controller | skipping: Conditional result was False 2025-12-25 00:13:34.823471 | 2025-12-25 00:13:34.823645 | PLAY RECAP 2025-12-25 00:13:34.823712 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-12-25 00:13:34.823739 | 2025-12-25 00:13:34.927480 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-12-25 00:13:34.929178 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-12-25 00:13:35.637558 | 2025-12-25 00:13:35.637736 | PLAY [all:!appliance*] 2025-12-25 00:13:35.666716 | 2025-12-25 00:13:35.666872 | TASK [unregister the node] 2025-12-25 00:13:36.206291 | controller | skipping: Conditional result was False 2025-12-25 00:13:36.221364 | 2025-12-25 00:13:36.221610 | TASK [include_role : fetch-output] 2025-12-25 00:13:36.260992 | controller | ok 2025-12-25 00:13:36.298714 | 2025-12-25 00:13:36.298863 | TASK [fetch-output : Set log path for multiple nodes] 2025-12-25 00:13:36.345171 | controller | skipping: Conditional result was False 2025-12-25 00:13:36.354562 | 2025-12-25 00:13:36.354665 | TASK [fetch-output : Set log path for single node] 2025-12-25 00:13:36.387787 | controller | ok 2025-12-25 00:13:36.395089 | 2025-12-25 00:13:36.395172 | LOOP [fetch-output : Ensure local output dirs] 2025-12-25 00:13:36.870051 | controller -> localhost | ok: "/var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/work/logs" 2025-12-25 00:13:37.124301 | controller -> localhost | changed: "/var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/work/artifacts" 2025-12-25 00:13:37.351123 | controller -> localhost | changed: "/var/lib/zuul/builds/43d69bd48e0648daa7e794e013a6f6c9/work/docs" 2025-12-25 00:13:37.363141 | 2025-12-25 00:13:37.363267 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-12-25 00:13:38.065590 | controller | changed: 2025-12-25 00:13:38.065814 | controller | .d..t...... ./ 2025-12-25 00:13:38.065842 | controller | cd+++++++++ controller/ 2025-12-25 00:13:38.065874 | controller | changed: All items complete 2025-12-25 00:13:38.065894 | 2025-12-25 00:13:38.557384 | controller | changed: .d..t...... ./ 2025-12-25 00:13:39.103381 | controller | changed: .d..t...... ./ 2025-12-25 00:13:39.133472 | 2025-12-25 00:13:39.133637 | TASK [include_role : fetch-output-openshift] 2025-12-25 00:13:39.149119 | controller | skipping: Conditional result was False 2025-12-25 00:13:39.157413 | 2025-12-25 00:13:39.157505 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-12-25 00:13:39.188269 | controller | skipping: Conditional result was False 2025-12-25 00:13:39.202345 | controller | skipping: Conditional result was False 2025-12-25 00:13:39.234080 | 2025-12-25 00:13:39.234233 | PLAY [localhost] 2025-12-25 00:13:39.247666 | 2025-12-25 00:13:39.247781 | TASK [Run Zuul manifest role] 2025-12-25 00:13:39.265813 | localhost | ok 2025-12-25 00:13:39.281077 | 2025-12-25 00:13:39.281215 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-12-25 00:13:39.681189 | localhost | changed 2025-12-25 00:13:39.696550 | 2025-12-25 00:13:39.696778 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-12-25 00:13:39.738380 | localhost | ok 2025-12-25 00:13:39.746778 | 2025-12-25 00:13:39.746843 | TASK [Set zuul-log-path fact] 2025-12-25 00:13:39.764939 | localhost | ok 2025-12-25 00:13:39.780428 | 2025-12-25 00:13:39.780519 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-12-25 00:13:39.822674 | localhost | ok 2025-12-25 00:13:39.839843 | 2025-12-25 00:13:39.839971 | LOOP [Run upload-logs-swift role] 2025-12-25 00:13:39.876618 | localhost | Output suppressed because no_log was given 2025-12-25 00:13:39.926277 | 2025-12-25 00:13:39.926440 | TASK [Set zuul-log-path fact] 2025-12-25 00:13:39.961932 | localhost | skipping: Conditional result was False 2025-12-25 00:13:39.968539 | 2025-12-25 00:13:39.968617 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-12-25 00:13:40.425058 | localhost -> localhost | ok: Runtime: 0:00:00.004979 2025-12-25 00:13:40.485011 | 2025-12-25 00:13:40.485169 | TASK [upload-logs-swift : Upload logs to swift]