2025-09-22 00:07:59.366223 | Job console starting... 2025-09-22 00:07:59.376594 | Updating repositories 2025-09-22 00:07:59.498578 | Preparing job workspace 2025-09-22 00:08:09.539247 | Running Ansible setup... 2025-09-22 00:08:17.711375 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-22 00:08:18.424816 | 2025-09-22 00:08:18.425109 | PLAY [localhost] 2025-09-22 00:08:18.434753 | 2025-09-22 00:08:18.434833 | TASK [Gathering Facts] 2025-09-22 00:08:19.469169 | localhost | ok 2025-09-22 00:08:19.498056 | 2025-09-22 00:08:19.498304 | TASK [Setup log path fact] 2025-09-22 00:08:19.520952 | localhost | ok 2025-09-22 00:08:19.537925 | 2025-09-22 00:08:19.538242 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-22 00:08:19.569950 | localhost | ok 2025-09-22 00:08:19.579559 | 2025-09-22 00:08:19.579722 | TASK [emit-job-header : Print job information] 2025-09-22 00:08:19.611141 | # Job Information 2025-09-22 00:08:19.611342 | Ansible Version: 2.15.12 2025-09-22 00:08:19.611373 | Job: ansible-test-sanity-docker-milestone 2025-09-22 00:08:19.611395 | Pipeline: periodic 2025-09-22 00:08:19.611414 | Executor: ze02.softwarefactory-project.io 2025-09-22 00:08:19.611435 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-09-22 00:08:19.611467 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/179/ansible/1791b9cfaf564d4d8cade2ecf04f09cd/ 2025-09-22 00:08:19.611488 | Event ID: 80fa768b351f40cb92b41db9ba32389a 2025-09-22 00:08:19.615791 | 2025-09-22 00:08:19.616104 | LOOP [emit-job-header : Print node information] 2025-09-22 00:08:19.720081 | localhost | ok: 2025-09-22 00:08:19.720308 | localhost | # Node Information 2025-09-22 00:08:19.720341 | localhost | Inventory Hostname: controller 2025-09-22 00:08:19.720361 | localhost | Hostname: np0005442646 2025-09-22 00:08:19.720380 | localhost | Username: zuul 2025-09-22 00:08:19.720399 | localhost | Distro: Fedora 37 2025-09-22 00:08:19.720415 | localhost | Provider: ansible-vexxhost-ams1 2025-09-22 00:08:19.720431 | localhost | Region: ams1 2025-09-22 00:08:19.720448 | localhost | Label: ansible-fedora-37-1vcpu 2025-09-22 00:08:19.720464 | localhost | Product Name: OpenStack Nova 2025-09-22 00:08:19.720480 | localhost | Interface IP: 38.129.16.227 2025-09-22 00:08:19.737351 | 2025-09-22 00:08:19.737512 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-22 00:08:20.224355 | localhost -> localhost | changed 2025-09-22 00:08:20.237404 | 2025-09-22 00:08:20.237614 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-22 00:08:21.166815 | localhost -> localhost | changed 2025-09-22 00:08:21.195421 | 2025-09-22 00:08:21.195549 | PLAY [all:!appliance*] 2025-09-22 00:08:21.213261 | 2025-09-22 00:08:21.213474 | TASK [include_role : start-zuul-console] 2025-09-22 00:08:21.242649 | controller | ok 2025-09-22 00:08:21.257809 | 2025-09-22 00:08:21.257960 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-22 00:08:22.437100 | controller | ok 2025-09-22 00:08:22.466420 | 2025-09-22 00:08:22.466575 | TASK [use-our-mirror : Retrieve the IP address] 2025-09-22 00:08:24.499509 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-09-22 00:08:24.511312 | 2025-09-22 00:08:24.511448 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-09-22 00:08:24.890327 | controller | skipping: Conditional result was False 2025-09-22 00:08:24.897486 | 2025-09-22 00:08:24.897554 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-09-22 00:08:24.943053 | controller | skipping: Conditional result was False 2025-09-22 00:08:24.959160 | 2025-09-22 00:08:24.959305 | TASK [use-our-mirror : Create the podman configuration directory] 2025-09-22 00:08:24.997598 | controller | skipping: Conditional result was False 2025-09-22 00:08:25.012457 | 2025-09-22 00:08:25.012604 | TASK [use-our-mirror : Copy the podman configuration] 2025-09-22 00:08:25.042223 | controller | skipping: Conditional result was False 2025-09-22 00:08:25.052175 | 2025-09-22 00:08:25.052266 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-09-22 00:08:25.085442 | controller | skipping: Conditional result was False 2025-09-22 00:08:25.092559 | 2025-09-22 00:08:25.092627 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-09-22 00:08:25.117817 | controller | skipping: Conditional result was False 2025-09-22 00:08:25.130021 | 2025-09-22 00:08:25.130115 | TASK [Disable Fedora Modular] 2025-09-22 00:08:26.293015 | controller | changed 2025-09-22 00:08:26.298608 | 2025-09-22 00:08:26.298698 | TASK [Enable EPEL] 2025-09-22 00:08:26.322911 | controller | skipping: Conditional result was False 2025-09-22 00:08:26.330207 | 2025-09-22 00:08:26.330298 | TASK [Register the RHEL node] 2025-09-22 00:08:26.752330 | 2025-09-22 00:08:26.752526 | TASK [Show the subscription-manager status] 2025-09-22 00:08:27.123840 | controller | skipping: Conditional result was False 2025-09-22 00:08:27.133138 | 2025-09-22 00:08:27.133226 | TASK [Enable EPEL on RHEL] 2025-09-22 00:08:27.533843 | controller | skipping: Conditional result was False 2025-09-22 00:08:27.549731 | 2025-09-22 00:08:27.549900 | TASK [Install git and tox] 2025-09-22 00:10:48.218363 | controller | changed 2025-09-22 00:10:48.236811 | 2025-09-22 00:10:48.236964 | TASK [include_role : prepare-workspace] 2025-09-22 00:10:48.279409 | controller | ok 2025-09-22 00:10:48.319041 | 2025-09-22 00:10:48.319323 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-22 00:10:49.203435 | controller | ok 2025-09-22 00:10:49.217683 | 2025-09-22 00:10:49.217826 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-22 00:11:06.156335 | controller | Output suppressed because no_log was given 2025-09-22 00:11:06.169920 | 2025-09-22 00:11:06.169987 | TASK [include_role : prepare-workspace-openshift] 2025-09-22 00:11:06.196723 | controller | skipping: Conditional result was False 2025-09-22 00:11:06.270009 | 2025-09-22 00:11:06.270163 | PLAY [all:!appliance] 2025-09-22 00:11:06.286262 | 2025-09-22 00:11:06.286323 | TASK [Run add-build-sshkey role (RSA)] 2025-09-22 00:11:06.316461 | controller | ok 2025-09-22 00:11:06.330968 | 2025-09-22 00:11:06.331034 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-22 00:11:06.568316 | controller -> localhost | ok 2025-09-22 00:11:06.575391 | 2025-09-22 00:11:06.575461 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-22 00:11:06.608841 | controller | ok 2025-09-22 00:11:06.623006 | controller | included: /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-22 00:11:06.629191 | 2025-09-22 00:11:06.629254 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-22 00:11:07.223095 | controller -> localhost | Generating public/private rsa key pair. 2025-09-22 00:11:07.223317 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/work/1791b9cfaf564d4d8cade2ecf04f09cd_id_rsa. 2025-09-22 00:11:07.223347 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/work/1791b9cfaf564d4d8cade2ecf04f09cd_id_rsa.pub. 2025-09-22 00:11:07.223369 | controller -> localhost | The key fingerprint is: 2025-09-22 00:11:07.223389 | controller -> localhost | SHA256:GeAJQgOzrtG/azop+M9pfcIVQ8uQBxp8CQB8WgZprXU zuul-build-sshkey 2025-09-22 00:11:07.223408 | controller -> localhost | The key's randomart image is: 2025-09-22 00:11:07.223428 | controller -> localhost | +---[RSA 2048]----+ 2025-09-22 00:11:07.223452 | controller -> localhost | |==Oo+.o+ | 2025-09-22 00:11:07.223472 | controller -> localhost | | * O.E=oo | 2025-09-22 00:11:07.223490 | controller -> localhost | |o B o.o=.. | 2025-09-22 00:11:07.223508 | controller -> localhost | |.+ =o | 2025-09-22 00:11:07.223525 | controller -> localhost | |... So | 2025-09-22 00:11:07.223552 | controller -> localhost | |.. . . | 2025-09-22 00:11:07.223581 | controller -> localhost | |o ..o . | 2025-09-22 00:11:07.223609 | controller -> localhost | |o o.oo+ . | 2025-09-22 00:11:07.223628 | controller -> localhost | | oo**. o | 2025-09-22 00:11:07.223648 | controller -> localhost | +----[SHA256]-----+ 2025-09-22 00:11:07.223724 | controller -> localhost | ok: Runtime: 0:00:00.201222 2025-09-22 00:11:07.231462 | 2025-09-22 00:11:07.231529 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-22 00:11:07.264532 | controller | ok 2025-09-22 00:11:07.278455 | controller | included: /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-22 00:11:07.287330 | 2025-09-22 00:11:07.287489 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-22 00:11:07.312386 | controller | skipping: Conditional result was False 2025-09-22 00:11:07.319635 | 2025-09-22 00:11:07.319784 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-22 00:11:08.482024 | controller | changed 2025-09-22 00:11:08.495805 | 2025-09-22 00:11:08.495907 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-22 00:11:09.321866 | controller | ok 2025-09-22 00:11:09.327597 | 2025-09-22 00:11:09.327661 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-22 00:11:12.597572 | controller | changed 2025-09-22 00:11:12.607506 | 2025-09-22 00:11:12.607615 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-22 00:11:15.807828 | controller | changed 2025-09-22 00:11:15.822022 | 2025-09-22 00:11:15.822122 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-22 00:11:15.852236 | controller | skipping: Conditional result was False 2025-09-22 00:11:15.863062 | 2025-09-22 00:11:15.863439 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-22 00:11:16.312474 | controller -> localhost | changed 2025-09-22 00:11:16.324779 | 2025-09-22 00:11:16.324876 | TASK [add-build-sshkey : Add back temp key] 2025-09-22 00:11:16.646032 | controller -> localhost | Identity added: /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/work/1791b9cfaf564d4d8cade2ecf04f09cd_id_rsa (zuul-build-sshkey) 2025-09-22 00:11:16.646301 | controller -> localhost | ok: Runtime: 0:00:00.019841 2025-09-22 00:11:16.653338 | 2025-09-22 00:11:16.653411 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-22 00:11:17.706368 | controller | ok 2025-09-22 00:11:17.719806 | 2025-09-22 00:11:17.720106 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-22 00:11:17.772792 | controller | skipping: Conditional result was False 2025-09-22 00:11:17.790619 | 2025-09-22 00:11:17.790762 | TASK [Run add-build-sshkey role (ECDSA)] 2025-09-22 00:11:17.827985 | controller | ok 2025-09-22 00:11:17.855706 | 2025-09-22 00:11:17.856056 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-22 00:11:18.158003 | controller -> localhost | ok 2025-09-22 00:11:18.168481 | 2025-09-22 00:11:18.171855 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-22 00:11:18.210392 | controller | ok 2025-09-22 00:11:18.234074 | controller | included: /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-22 00:11:18.259279 | 2025-09-22 00:11:18.259485 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-22 00:11:18.613144 | controller -> localhost | Generating public/private ecdsa key pair. 2025-09-22 00:11:18.613371 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/work/1791b9cfaf564d4d8cade2ecf04f09cd_id_ecdsa. 2025-09-22 00:11:18.613399 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/work/1791b9cfaf564d4d8cade2ecf04f09cd_id_ecdsa.pub. 2025-09-22 00:11:18.613428 | controller -> localhost | The key fingerprint is: 2025-09-22 00:11:18.613448 | controller -> localhost | SHA256:S9Xv5044TC7W4xf9sGi7zrsQUNfMKO9fyXsse1ut8M0 zuul-build-sshkey 2025-09-22 00:11:18.613467 | controller -> localhost | The key's randomart image is: 2025-09-22 00:11:18.613484 | controller -> localhost | +---[ECDSA 521]---+ 2025-09-22 00:11:18.613501 | controller -> localhost | | . .= | 2025-09-22 00:11:18.613518 | controller -> localhost | | ..o. + | 2025-09-22 00:11:18.613535 | controller -> localhost | | . .o. | 2025-09-22 00:11:18.613551 | controller -> localhost | | o .. | 2025-09-22 00:11:18.613568 | controller -> localhost | | S .. + o| 2025-09-22 00:11:18.613584 | controller -> localhost | | . . ..*.=+| 2025-09-22 00:11:18.613601 | controller -> localhost | | . . +oO=O| 2025-09-22 00:11:18.613617 | controller -> localhost | | +o=+@B| 2025-09-22 00:11:18.613633 | controller -> localhost | | oB==BE| 2025-09-22 00:11:18.613649 | controller -> localhost | +----[SHA256]-----+ 2025-09-22 00:11:18.613717 | controller -> localhost | ok: Runtime: 0:00:00.014506 2025-09-22 00:11:18.621956 | 2025-09-22 00:11:18.622065 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-22 00:11:18.652285 | controller | ok 2025-09-22 00:11:18.659591 | controller | included: /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-22 00:11:18.668365 | 2025-09-22 00:11:18.668434 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-22 00:11:18.692811 | controller | skipping: Conditional result was False 2025-09-22 00:11:18.699111 | 2025-09-22 00:11:18.699177 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-22 00:11:19.691692 | controller | changed 2025-09-22 00:11:19.699384 | 2025-09-22 00:11:19.699468 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-22 00:11:20.402056 | controller | ok 2025-09-22 00:11:20.415646 | 2025-09-22 00:11:20.415818 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-22 00:11:23.573231 | controller | changed 2025-09-22 00:11:23.582560 | 2025-09-22 00:11:23.582683 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-22 00:11:26.778160 | controller | changed 2025-09-22 00:11:26.784420 | 2025-09-22 00:11:26.784488 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-22 00:11:26.825296 | controller | skipping: Conditional result was False 2025-09-22 00:11:26.833980 | 2025-09-22 00:11:26.834103 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-22 00:11:27.105242 | controller -> localhost | changed 2025-09-22 00:11:27.117587 | 2025-09-22 00:11:27.117733 | TASK [add-build-sshkey : Add back temp key] 2025-09-22 00:11:27.416129 | controller -> localhost | Identity added: /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/work/1791b9cfaf564d4d8cade2ecf04f09cd_id_ecdsa (zuul-build-sshkey) 2025-09-22 00:11:27.416470 | controller -> localhost | ok: Runtime: 0:00:00.014745 2025-09-22 00:11:27.424355 | 2025-09-22 00:11:27.424480 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-22 00:11:28.218251 | controller | ok 2025-09-22 00:11:28.234810 | 2025-09-22 00:11:28.235157 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-22 00:11:28.275242 | controller | skipping: Conditional result was False 2025-09-22 00:11:28.299294 | 2025-09-22 00:11:28.299387 | TASK [include_role : remove-zuul-sshkey] 2025-09-22 00:11:28.325979 | controller | skipping: Conditional result was False 2025-09-22 00:11:28.335227 | 2025-09-22 00:11:28.335348 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-22 00:11:29.052101 | controller | ok: "logs" 2025-09-22 00:11:29.054414 | controller | ok: All items complete 2025-09-22 00:11:29.054467 | 2025-09-22 00:11:29.716603 | controller | ok: "artifacts" 2025-09-22 00:11:30.449025 | controller | ok: "docs" 2025-09-22 00:11:30.471333 | 2025-09-22 00:11:30.471500 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-22 00:11:31.239932 | controller | changed: "logs" 2025-09-22 00:11:31.983386 | controller | changed: "artifacts" 2025-09-22 00:11:32.729941 | controller | changed: "docs" 2025-09-22 00:11:32.761890 | 2025-09-22 00:11:32.762014 | PLAY RECAP 2025-09-22 00:11:32.762060 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-09-22 00:11:32.762085 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-22 00:11:32.762102 | 2025-09-22 00:11:32.977363 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-22 00:11:32.978372 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-22 00:11:33.661428 | 2025-09-22 00:11:33.661574 | PLAY [all] 2025-09-22 00:11:33.687189 | 2025-09-22 00:11:33.687298 | TASK [Install binary dependencies] 2025-09-22 00:11:33.750319 | controller | ok 2025-09-22 00:11:33.774730 | 2025-09-22 00:11:33.774877 | TASK [bindep : Include find tasks] 2025-09-22 00:11:33.806433 | controller | ok 2025-09-22 00:11:33.817922 | controller | included: /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-22 00:11:33.824192 | 2025-09-22 00:11:33.824264 | TASK [bindep : Look for bindep.txt] 2025-09-22 00:11:34.859008 | controller | ok 2025-09-22 00:11:34.874639 | 2025-09-22 00:11:34.874898 | TASK [bindep : Define bindep_file fact] 2025-09-22 00:11:34.902968 | controller | skipping: Conditional result was False 2025-09-22 00:11:34.913125 | 2025-09-22 00:11:34.913281 | TASK [bindep : Look for other-requirements.txt] 2025-09-22 00:11:35.590757 | controller | ok 2025-09-22 00:11:35.602438 | 2025-09-22 00:11:35.602596 | TASK [bindep : Define bindep_file fact] 2025-09-22 00:11:35.629441 | controller | skipping: Conditional result was False 2025-09-22 00:11:35.643748 | 2025-09-22 00:11:35.643953 | TASK [bindep : Look for bindep fallback file] 2025-09-22 00:11:35.673218 | controller | skipping: Conditional result was False 2025-09-22 00:11:35.684349 | 2025-09-22 00:11:35.684560 | TASK [bindep : Define bindep_file fact] 2025-09-22 00:11:35.722157 | controller | skipping: Conditional result was False 2025-09-22 00:11:35.734590 | 2025-09-22 00:11:35.735335 | TASK [bindep : Include bindep tasks] 2025-09-22 00:11:35.765197 | controller | skipping: Conditional result was False 2025-09-22 00:11:35.777189 | 2025-09-22 00:11:35.777364 | TASK [bindep : Include install tasks] 2025-09-22 00:11:35.814934 | controller | skipping: Conditional result was False 2025-09-22 00:11:35.822584 | 2025-09-22 00:11:35.822715 | LOOP [bindep : Include package tasks] 2025-09-22 00:11:35.896851 | 2025-09-22 00:11:35.897093 | TASK [Run test-setup role] 2025-09-22 00:11:35.921031 | controller | ok 2025-09-22 00:11:35.946909 | 2025-09-22 00:11:35.947026 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-22 00:11:36.688536 | controller | ok 2025-09-22 00:11:36.706344 | 2025-09-22 00:11:36.706543 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-22 00:11:37.081570 | controller | skipping: Conditional result was False 2025-09-22 00:11:37.137566 | 2025-09-22 00:11:37.137738 | PLAY RECAP 2025-09-22 00:11:37.137795 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-22 00:11:37.137824 | 2025-09-22 00:11:37.299772 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-22 00:11:37.300755 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-22 00:11:38.008937 | 2025-09-22 00:11:38.009109 | PLAY [controller] 2025-09-22 00:11:38.030553 | 2025-09-22 00:11:38.030719 | TASK [Create the /root directory] 2025-09-22 00:11:39.145821 | controller | ok 2025-09-22 00:11:39.161967 | 2025-09-22 00:11:39.162168 | TASK [Install glibc-langpack-en] 2025-09-22 00:11:48.160832 | controller | ok: Nothing to do 2025-09-22 00:11:48.173878 | 2025-09-22 00:11:48.174083 | TASK [Ensure controller directory exists] 2025-09-22 00:11:49.089427 | controller | changed 2025-09-22 00:11:49.101839 | 2025-09-22 00:11:49.101970 | TASK [Install container runtime] 2025-09-22 00:11:49.175493 | controller | ok 2025-09-22 00:11:49.212307 | 2025-09-22 00:11:49.212443 | LOOP [ensure-podman : Find distribution installation] 2025-09-22 00:11:49.236105 | controller | ok: "/var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-09-22 00:11:49.246985 | controller | included: /var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-09-22 00:11:49.254108 | 2025-09-22 00:11:49.254200 | TASK [ensure-podman : Install podman (RedHat)] 2025-09-22 00:14:02.241941 | controller | changed 2025-09-22 00:14:02.258342 | 2025-09-22 00:14:02.258534 | TASK [ensure-podman : Fetch podman version] 2025-09-22 00:14:03.779175 | controller | Client: Podman Engine 2025-09-22 00:14:03.815990 | controller | Version: 4.6.2 2025-09-22 00:14:03.816046 | controller | API Version: 4.6.2 2025-09-22 00:14:03.816055 | controller | Go Version: go1.19.12 2025-09-22 00:14:03.816075 | controller | Built: Mon Aug 28 19:38:31 2023 2025-09-22 00:14:03.816083 | controller | OS/Arch: linux/amd64 2025-09-22 00:14:04.139940 | controller | ok: Runtime: 0:00:00.267913 2025-09-22 00:14:04.155557 | 2025-09-22 00:14:04.155737 | TASK [ensure-podman : Print podman version installed] 2025-09-22 00:14:04.195837 | Podman version: Client: Podman Engine 2025-09-22 00:14:04.196120 | Version: 4.6.2 2025-09-22 00:14:04.196203 | API Version: 4.6.2 2025-09-22 00:14:04.196251 | Go Version: go1.19.12 2025-09-22 00:14:04.196292 | Built: Mon Aug 28 19:38:31 2023 2025-09-22 00:14:04.196333 | OS/Arch: linux/amd64 2025-09-22 00:14:04.209431 | 2025-09-22 00:14:04.209561 | TASK [ensure-podman : Validate podman engine] 2025-09-22 00:14:04.577405 | controller | skipping: Conditional result was False 2025-09-22 00:14:04.591790 | 2025-09-22 00:14:04.591941 | TASK [ensure-podman : Set up docker compatability socket] 2025-09-22 00:14:04.608895 | controller | skipping: Conditional result was False 2025-09-22 00:14:04.636742 | 2025-09-22 00:14:04.636921 | TASK [Ensure python3.8 is present] 2025-09-22 00:14:04.653830 | controller | skipping: Conditional result was False 2025-09-22 00:14:04.660354 | 2025-09-22 00:14:04.660423 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-09-22 00:14:04.682243 | controller | ok 2025-09-22 00:14:04.709042 | 2025-09-22 00:14:04.709175 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-09-22 00:14:08.441631 | controller | ok: Nothing to do 2025-09-22 00:14:08.458131 | 2025-09-22 00:14:08.458283 | TASK [our-ensure-python : Also install python3-devel] 2025-09-22 00:14:24.344299 | controller | changed 2025-09-22 00:14:24.361541 | 2025-09-22 00:14:24.361726 | TASK [Run ensure-virtualenv role] 2025-09-22 00:14:24.388696 | controller | ok 2025-09-22 00:14:24.421884 | 2025-09-22 00:14:24.422045 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-09-22 00:14:25.241284 | controller | /usr/bin/virtualenv 2025-09-22 00:14:25.816844 | controller | ok: Runtime: 0:00:00.004671 2025-09-22 00:14:25.829797 | 2025-09-22 00:14:25.829966 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-09-22 00:14:25.851130 | controller | skipping: Conditional result was False 2025-09-22 00:14:25.851433 | controller | ok: All items complete 2025-09-22 00:14:25.851461 | 2025-09-22 00:14:25.881935 | 2025-09-22 00:14:25.882161 | TASK [Find the full path of the Python interpreter] 2025-09-22 00:14:26.841323 | controller | /usr/bin/python3 2025-09-22 00:14:27.257421 | controller | ok 2025-09-22 00:14:27.271033 | 2025-09-22 00:14:27.271235 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-09-22 00:14:29.182716 | controller | created virtual environment CPython3.11.0.final.0-64 in 895ms 2025-09-22 00:14:29.241511 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-09-22 00:14:29.241566 | 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-09-22 00:14:29.241583 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-09-22 00:14:29.241603 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-09-22 00:14:29.673795 | controller | changed 2025-09-22 00:14:29.686703 | 2025-09-22 00:14:29.686843 | TASK [Set selinux package] 2025-09-22 00:14:29.709242 | controller | ok 2025-09-22 00:14:29.714689 | 2025-09-22 00:14:29.714753 | TASK [Set selinux package (Fedora)] 2025-09-22 00:14:29.743937 | controller | ok 2025-09-22 00:14:29.749112 | 2025-09-22 00:14:29.749181 | TASK [Install selinux into virtualenv] 2025-09-22 00:14:33.100816 | controller | Collecting selinux-please-lie-to-me 2025-09-22 00:14:33.457484 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-09-22 00:14:34.031482 | controller | Collecting setuptools<50.0.0 2025-09-22 00:14:34.038689 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-09-22 00:14:34.097825 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 16.5 MB/s eta 0:00:00 2025-09-22 00:14:34.259979 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-09-22 00:14:34.260311 | controller | Attempting uninstall: setuptools 2025-09-22 00:14:34.265857 | controller | Found existing installation: setuptools 62.6.0 2025-09-22 00:14:34.379887 | controller | Uninstalling setuptools-62.6.0: 2025-09-22 00:14:34.394177 | controller | Successfully uninstalled setuptools-62.6.0 2025-09-22 00:14:35.271807 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-09-22 00:14:35.487062 | controller | 2025-09-22 00:14:35.789291 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-22 00:14:35.789332 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-22 00:14:36.132096 | controller | ok: Runtime: 0:00:05.127707 2025-09-22 00:14:36.146120 | 2025-09-22 00:14:36.146271 | TASK [Install pytest-forked into virtualenv] 2025-09-22 00:14:37.774265 | controller | Collecting pytest-forked 2025-09-22 00:14:37.863659 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-09-22 00:14:37.938723 | controller | Collecting py 2025-09-22 00:14:37.944140 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-09-22 00:14:37.994963 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.0 MB/s eta 0:00:00 2025-09-22 00:14:38.217453 | controller | Collecting pytest>=3.10 2025-09-22 00:14:38.223726 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-09-22 00:14:38.257220 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 14.7 MB/s eta 0:00:00 2025-09-22 00:14:38.327063 | controller | Collecting iniconfig>=1 2025-09-22 00:14:38.332503 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-09-22 00:14:38.437961 | controller | Collecting packaging>=20 2025-09-22 00:14:38.448489 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-09-22 00:14:38.474305 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 3.2 MB/s eta 0:00:00 2025-09-22 00:14:38.524074 | controller | Collecting pluggy<2,>=1.5 2025-09-22 00:14:38.532329 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-09-22 00:14:38.616276 | controller | Collecting pygments>=2.7.2 2025-09-22 00:14:38.623085 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-09-22 00:14:38.663252 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 35.0 MB/s eta 0:00:00 2025-09-22 00:14:38.797146 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-09-22 00:14:41.287517 | controller | Successfully installed iniconfig-2.1.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0 2025-09-22 00:14:41.305355 | controller | 2025-09-22 00:14:41.578863 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-22 00:14:41.578912 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-22 00:14:42.050134 | controller | ok: Runtime: 0:00:04.586677 2025-09-22 00:14:42.064228 | 2025-09-22 00:14:42.064393 | TASK [Update pip] 2025-09-22 00:14:43.536801 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-09-22 00:14:43.824644 | controller | Collecting pip 2025-09-22 00:14:43.901295 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-09-22 00:14:43.995263 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 20.9 MB/s eta 0:00:00 2025-09-22 00:14:44.128297 | controller | Installing collected packages: pip 2025-09-22 00:14:44.128515 | controller | Attempting uninstall: pip 2025-09-22 00:14:44.131846 | controller | Found existing installation: pip 22.2.2 2025-09-22 00:14:44.399500 | controller | Uninstalling pip-22.2.2: 2025-09-22 00:14:44.432466 | controller | Successfully uninstalled pip-22.2.2 2025-09-22 00:14:46.381427 | controller | Successfully installed pip-25.2 2025-09-22 00:14:46.949063 | controller | ok: Runtime: 0:00:03.677847 2025-09-22 00:14:46.965113 | 2025-09-22 00:14:46.965279 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-09-22 00:14:47.901696 | controller | changed 2025-09-22 00:14:47.913311 | 2025-09-22 00:14:47.913445 | TASK [Install ansible into virtualenv] 2025-09-22 00:14:49.335126 | controller | Processing ./src/github.com/ansible/ansible 2025-09-22 00:14:49.341804 | controller | Installing build dependencies: started 2025-09-22 00:14:51.437297 | controller | Installing build dependencies: finished with status 'done' 2025-09-22 00:14:53.168263 | controller | Getting requirements to build wheel: started 2025-09-22 00:14:53.168325 | controller | Getting requirements to build wheel: finished with status 'done' 2025-09-22 00:14:53.171812 | controller | Preparing metadata (pyproject.toml): started 2025-09-22 00:14:54.084273 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-09-22 00:14:54.087264 | 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-09-22 00:14:54.093071 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-09-22 00:14:54.821770 | controller | ERROR 2025-09-22 00:14:54.822010 | controller | { 2025-09-22 00:14:54.822041 | controller | "delta": "0:00:05.662163", 2025-09-22 00:14:54.822061 | controller | "end": "2025-09-22 00:14:54.287480", 2025-09-22 00:14:54.822081 | controller | "msg": "non-zero return code", 2025-09-22 00:14:54.822116 | controller | "rc": 1, 2025-09-22 00:14:54.822134 | controller | "start": "2025-09-22 00:14:48.625317" 2025-09-22 00:14:54.822150 | controller | } failure 2025-09-22 00:14:54.824355 | 2025-09-22 00:14:54.824417 | PLAY RECAP 2025-09-22 00:14:54.824475 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-09-22 00:14:54.824502 | 2025-09-22 00:14:54.954651 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-22 00:14:54.956615 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-22 00:14:55.566028 | 2025-09-22 00:14:55.566181 | PLAY [all] 2025-09-22 00:14:55.590393 | 2025-09-22 00:14:55.590631 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-22 00:14:57.514095 | controller | changed: non-zero return code 2025-09-22 00:14:57.528090 | 2025-09-22 00:14:57.528298 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-22 00:14:57.543937 | controller | skipping: Conditional result was False 2025-09-22 00:14:57.555354 | 2025-09-22 00:14:57.555516 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-22 00:14:57.591555 | 2025-09-22 00:14:57.591799 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-22 00:14:57.630081 | 2025-09-22 00:14:57.630359 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-22 00:14:57.646801 | controller | skipping: Conditional result was False 2025-09-22 00:14:57.658052 | 2025-09-22 00:14:57.658194 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-22 00:14:57.691738 | 2025-09-22 00:14:57.691950 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-22 00:14:57.707720 | controller | skipping: Conditional result was False 2025-09-22 00:14:57.716824 | 2025-09-22 00:14:57.716950 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-22 00:14:57.732487 | controller | skipping: Conditional result was False 2025-09-22 00:14:57.743067 | 2025-09-22 00:14:57.743213 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-22 00:14:57.767927 | controller | skipping: Conditional result was False 2025-09-22 00:14:57.807462 | 2025-09-22 00:14:57.807579 | PLAY RECAP 2025-09-22 00:14:57.807619 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-22 00:14:57.807639 | 2025-09-22 00:14:57.911479 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-22 00:14:57.913225 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-09-22 00:14:58.552055 | 2025-09-22 00:14:58.552292 | PLAY [all:!appliance*] 2025-09-22 00:14:58.587735 | 2025-09-22 00:14:58.587912 | TASK [unregister the node] 2025-09-22 00:14:58.954219 | controller | skipping: Conditional result was False 2025-09-22 00:14:58.966584 | 2025-09-22 00:14:58.966782 | TASK [include_role : fetch-output] 2025-09-22 00:14:59.026768 | controller | ok 2025-09-22 00:14:59.068520 | 2025-09-22 00:14:59.068649 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-22 00:14:59.114561 | controller | skipping: Conditional result was False 2025-09-22 00:14:59.122876 | 2025-09-22 00:14:59.122991 | TASK [fetch-output : Set log path for single node] 2025-09-22 00:14:59.165705 | controller | ok 2025-09-22 00:14:59.173527 | 2025-09-22 00:14:59.173631 | LOOP [fetch-output : Ensure local output dirs] 2025-09-22 00:14:59.595994 | controller -> localhost | ok: "/var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/work/logs" 2025-09-22 00:14:59.821647 | controller -> localhost | changed: "/var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/work/artifacts" 2025-09-22 00:15:00.077521 | controller -> localhost | changed: "/var/lib/zuul/builds/1791b9cfaf564d4d8cade2ecf04f09cd/work/docs" 2025-09-22 00:15:00.094252 | 2025-09-22 00:15:00.094369 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-22 00:15:02.384991 | controller | changed: 2025-09-22 00:15:02.385762 | controller | .d..t...... ./ 2025-09-22 00:15:02.385870 | controller | cd+++++++++ controller/ 2025-09-22 00:15:02.385971 | controller | changed: All items complete 2025-09-22 00:15:02.386036 | 2025-09-22 00:15:04.449484 | controller | changed: .d..t...... ./ 2025-09-22 00:15:06.556605 | controller | changed: .d..t...... ./ 2025-09-22 00:15:06.588492 | 2025-09-22 00:15:06.588722 | TASK [include_role : fetch-output-openshift] 2025-09-22 00:15:06.615240 | controller | skipping: Conditional result was False 2025-09-22 00:15:06.629952 | 2025-09-22 00:15:06.630116 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-22 00:15:06.663263 | controller | skipping: Conditional result was False 2025-09-22 00:15:06.671297 | controller | skipping: Conditional result was False 2025-09-22 00:15:06.726780 | 2025-09-22 00:15:06.726897 | PLAY [localhost] 2025-09-22 00:15:06.745354 | 2025-09-22 00:15:06.745450 | TASK [Run Zuul manifest role] 2025-09-22 00:15:06.765243 | localhost | ok 2025-09-22 00:15:06.784508 | 2025-09-22 00:15:06.784630 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-22 00:15:07.165061 | localhost | changed 2025-09-22 00:15:07.174922 | 2025-09-22 00:15:07.175058 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-22 00:15:07.220412 | localhost | ok 2025-09-22 00:15:07.239512 | 2025-09-22 00:15:07.239656 | TASK [Set zuul-log-path fact] 2025-09-22 00:15:07.300577 | localhost | ok 2025-09-22 00:15:07.318728 | 2025-09-22 00:15:07.318862 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-22 00:15:07.350335 | localhost | ok 2025-09-22 00:15:07.362095 | 2025-09-22 00:15:07.362178 | LOOP [Run upload-logs-swift role] 2025-09-22 00:15:07.407079 | localhost | Output suppressed because no_log was given 2025-09-22 00:15:07.443593 | 2025-09-22 00:15:07.443742 | TASK [Set zuul-log-path fact] 2025-09-22 00:15:07.469555 | localhost | skipping: Conditional result was False 2025-09-22 00:15:07.477372 | 2025-09-22 00:15:07.477551 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-09-22 00:15:07.920022 | localhost -> localhost | ok: Runtime: 0:00:00.009218 2025-09-22 00:15:07.925944 | 2025-09-22 00:15:07.926009 | TASK [upload-logs-swift : Upload logs to swift]