2025-09-24 00:06:31.215790 | Job console starting... 2025-09-24 00:06:31.230492 | Updating repositories 2025-09-24 00:06:35.151143 | Preparing job workspace 2025-09-24 00:06:41.779333 | Running Ansible setup... 2025-09-24 00:06:48.401666 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-24 00:06:49.083379 | 2025-09-24 00:06:49.083513 | PLAY [localhost] 2025-09-24 00:06:49.091930 | 2025-09-24 00:06:49.092054 | TASK [Gathering Facts] 2025-09-24 00:06:50.107193 | localhost | ok 2025-09-24 00:06:50.129819 | 2025-09-24 00:06:50.130051 | TASK [Setup log path fact] 2025-09-24 00:06:50.149542 | localhost | ok 2025-09-24 00:06:50.168405 | 2025-09-24 00:06:50.168512 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-24 00:06:50.196341 | localhost | ok 2025-09-24 00:06:50.204162 | 2025-09-24 00:06:50.204232 | TASK [emit-job-header : Print job information] 2025-09-24 00:06:50.232273 | # Job Information 2025-09-24 00:06:50.232487 | Ansible Version: 2.15.12 2025-09-24 00:06:50.232521 | Job: ansible-test-sanity-docker-milestone 2025-09-24 00:06:50.232543 | Pipeline: periodic 2025-09-24 00:06:50.232562 | Executor: ze01.softwarefactory-project.io 2025-09-24 00:06:50.232579 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-09-24 00:06:50.232600 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/840/ansible/840fb62e78834f738ae3665b8fcb2278/ 2025-09-24 00:06:50.232619 | Event ID: 3b09a8e0ff9c49ffb90e8d2a452c8a0a 2025-09-24 00:06:50.237663 | 2025-09-24 00:06:50.237736 | LOOP [emit-job-header : Print node information] 2025-09-24 00:06:50.378324 | localhost | ok: 2025-09-24 00:06:50.378540 | localhost | # Node Information 2025-09-24 00:06:50.378577 | localhost | Inventory Hostname: controller 2025-09-24 00:06:50.378601 | localhost | Hostname: ip-172-16-233-16 2025-09-24 00:06:50.378623 | localhost | Username: zuul-worker 2025-09-24 00:06:50.378646 | localhost | Distro: Fedora 37 2025-09-24 00:06:50.378666 | localhost | Provider: ansible-us-east-2 2025-09-24 00:06:50.378685 | localhost | Region: us-east-2 2025-09-24 00:06:50.378703 | localhost | Label: ansible-fedora-37-1vcpu 2025-09-24 00:06:50.378725 | localhost | Product Name: t3.small 2025-09-24 00:06:50.378744 | localhost | Interface IP: 52.15.64.14 2025-09-24 00:06:50.398207 | 2025-09-24 00:06:50.398353 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-09-24 00:06:50.819411 | localhost -> localhost | changed 2025-09-24 00:06:50.825084 | 2025-09-24 00:06:50.825154 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-09-24 00:06:51.770689 | localhost -> localhost | changed 2025-09-24 00:06:51.793955 | 2025-09-24 00:06:51.794053 | PLAY [all:!appliance*] 2025-09-24 00:06:51.809422 | 2025-09-24 00:06:51.809485 | TASK [include_role : start-zuul-console] 2025-09-24 00:06:51.827944 | controller | ok 2025-09-24 00:06:51.841616 | 2025-09-24 00:06:51.841690 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-09-24 00:06:52.497772 | controller | ok 2025-09-24 00:06:52.521240 | 2025-09-24 00:06:52.521350 | TASK [use-our-mirror : Retrieve the IP address] 2025-09-24 00:06:53.740728 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-09-24 00:06:53.746694 | 2025-09-24 00:06:53.746759 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-09-24 00:06:53.890986 | controller | skipping: Conditional result was False 2025-09-24 00:06:53.897148 | 2025-09-24 00:06:53.897219 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-09-24 00:06:53.921314 | controller | skipping: Conditional result was False 2025-09-24 00:06:53.928664 | 2025-09-24 00:06:53.928742 | TASK [use-our-mirror : Create the podman configuration directory] 2025-09-24 00:06:53.943086 | controller | skipping: Conditional result was False 2025-09-24 00:06:53.950440 | 2025-09-24 00:06:53.950530 | TASK [use-our-mirror : Copy the podman configuration] 2025-09-24 00:06:53.967064 | controller | skipping: Conditional result was False 2025-09-24 00:06:53.973611 | 2025-09-24 00:06:53.973702 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-09-24 00:06:53.990931 | controller | skipping: Conditional result was False 2025-09-24 00:06:53.997996 | 2025-09-24 00:06:53.998117 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-09-24 00:06:54.052438 | controller | skipping: Conditional result was False 2025-09-24 00:06:54.064262 | 2025-09-24 00:06:54.064353 | TASK [Disable Fedora Modular] 2025-09-24 00:06:54.695275 | controller | changed 2025-09-24 00:06:54.705918 | 2025-09-24 00:06:54.706066 | TASK [Enable EPEL] 2025-09-24 00:06:54.742671 | controller | skipping: Conditional result was False 2025-09-24 00:06:54.751842 | 2025-09-24 00:06:54.751961 | TASK [Register the RHEL node] 2025-09-24 00:06:54.905618 | 2025-09-24 00:06:54.905776 | TASK [Show the subscription-manager status] 2025-09-24 00:06:55.058242 | controller | skipping: Conditional result was False 2025-09-24 00:06:55.127166 | 2025-09-24 00:06:55.127311 | TASK [Enable EPEL on RHEL] 2025-09-24 00:06:55.292776 | controller | skipping: Conditional result was False 2025-09-24 00:06:55.298667 | 2025-09-24 00:06:55.298737 | TASK [Install git and tox] 2025-09-24 00:08:16.169287 | controller | changed 2025-09-24 00:08:16.195727 | 2025-09-24 00:08:16.195884 | TASK [include_role : prepare-workspace] 2025-09-24 00:08:16.231739 | controller | ok 2025-09-24 00:08:16.256953 | 2025-09-24 00:08:16.257079 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-09-24 00:08:16.721585 | controller | ok 2025-09-24 00:08:16.737051 | 2025-09-24 00:08:16.737184 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-09-24 00:08:31.395879 | controller | Output suppressed because no_log was given 2025-09-24 00:08:31.407522 | 2025-09-24 00:08:31.407594 | TASK [include_role : prepare-workspace-openshift] 2025-09-24 00:08:31.432404 | controller | skipping: Conditional result was False 2025-09-24 00:08:31.455160 | 2025-09-24 00:08:31.455225 | PLAY [all:!appliance] 2025-09-24 00:08:31.502549 | 2025-09-24 00:08:31.502684 | TASK [Run add-build-sshkey role (RSA)] 2025-09-24 00:08:31.532325 | controller | ok 2025-09-24 00:08:31.553531 | 2025-09-24 00:08:31.553681 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-24 00:08:31.802925 | controller -> localhost | ok 2025-09-24 00:08:31.811724 | 2025-09-24 00:08:31.811827 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-24 00:08:31.846588 | controller | ok 2025-09-24 00:08:31.882861 | controller | included: /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-24 00:08:31.893376 | 2025-09-24 00:08:31.893546 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-24 00:08:32.525786 | controller -> localhost | Generating public/private rsa key pair. 2025-09-24 00:08:32.525955 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/work/840fb62e78834f738ae3665b8fcb2278_id_rsa. 2025-09-24 00:08:32.525985 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/work/840fb62e78834f738ae3665b8fcb2278_id_rsa.pub. 2025-09-24 00:08:32.526010 | controller -> localhost | The key fingerprint is: 2025-09-24 00:08:32.526063 | controller -> localhost | SHA256:Ani3ntXOshbEDb+wJWXMN2pW/ScgU2ivkWd2oMAnbeM zuul-build-sshkey 2025-09-24 00:08:32.526084 | controller -> localhost | The key's randomart image is: 2025-09-24 00:08:32.526104 | controller -> localhost | +---[RSA 2048]----+ 2025-09-24 00:08:32.526122 | controller -> localhost | | . + o.. | 2025-09-24 00:08:32.526141 | controller -> localhost | | . = # * . | 2025-09-24 00:08:32.526159 | controller -> localhost | | . o .. & @ + . | 2025-09-24 00:08:32.526177 | controller -> localhost | | . o .=.E = o o| 2025-09-24 00:08:32.526194 | controller -> localhost | | o.SB.B . ..| 2025-09-24 00:08:32.526221 | controller -> localhost | | . +ooo | 2025-09-24 00:08:32.526244 | controller -> localhost | | o ..o | 2025-09-24 00:08:32.526266 | controller -> localhost | | .o | 2025-09-24 00:08:32.526286 | controller -> localhost | | .. | 2025-09-24 00:08:32.526307 | controller -> localhost | +----[SHA256]-----+ 2025-09-24 00:08:32.526351 | controller -> localhost | ok: Runtime: 0:00:00.168437 2025-09-24 00:08:32.534906 | 2025-09-24 00:08:32.535044 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-24 00:08:32.576944 | controller | ok 2025-09-24 00:08:32.594009 | controller | included: /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-24 00:08:32.603477 | 2025-09-24 00:08:32.603589 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-24 00:08:32.644268 | controller | skipping: Conditional result was False 2025-09-24 00:08:32.654119 | 2025-09-24 00:08:32.654236 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-24 00:08:33.324494 | controller | changed 2025-09-24 00:08:33.341481 | 2025-09-24 00:08:33.341897 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-24 00:08:33.709750 | controller | ok 2025-09-24 00:08:33.717222 | 2025-09-24 00:08:33.717327 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-24 00:08:35.013145 | controller | changed 2025-09-24 00:08:35.020252 | 2025-09-24 00:08:35.020319 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-24 00:08:36.322291 | controller | changed 2025-09-24 00:08:36.334082 | 2025-09-24 00:08:36.334185 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-24 00:08:36.391159 | controller | skipping: Conditional result was False 2025-09-24 00:08:36.399009 | 2025-09-24 00:08:36.399110 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-24 00:08:36.862176 | controller -> localhost | changed 2025-09-24 00:08:36.882104 | 2025-09-24 00:08:36.882249 | TASK [add-build-sshkey : Add back temp key] 2025-09-24 00:08:37.198476 | controller -> localhost | Identity added: /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/work/840fb62e78834f738ae3665b8fcb2278_id_rsa (zuul-build-sshkey) 2025-09-24 00:08:37.198675 | controller -> localhost | ok: Runtime: 0:00:00.010396 2025-09-24 00:08:37.205467 | 2025-09-24 00:08:37.205571 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-24 00:08:37.737560 | controller | ok 2025-09-24 00:08:37.749181 | 2025-09-24 00:08:37.749329 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-24 00:08:37.777525 | controller | skipping: Conditional result was False 2025-09-24 00:08:37.795783 | 2025-09-24 00:08:37.795927 | TASK [Run add-build-sshkey role (ECDSA)] 2025-09-24 00:08:37.829387 | controller | ok 2025-09-24 00:08:37.855401 | 2025-09-24 00:08:37.856652 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-09-24 00:08:38.117008 | controller -> localhost | ok 2025-09-24 00:08:38.128314 | 2025-09-24 00:08:38.128462 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-09-24 00:08:38.159758 | controller | ok 2025-09-24 00:08:38.171770 | controller | included: /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-09-24 00:08:38.178905 | 2025-09-24 00:08:38.178990 | TASK [add-build-sshkey : Create Temp SSH key] 2025-09-24 00:08:38.513227 | controller -> localhost | Generating public/private ecdsa key pair. 2025-09-24 00:08:38.513442 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/work/840fb62e78834f738ae3665b8fcb2278_id_ecdsa. 2025-09-24 00:08:38.513473 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/work/840fb62e78834f738ae3665b8fcb2278_id_ecdsa.pub. 2025-09-24 00:08:38.513502 | controller -> localhost | The key fingerprint is: 2025-09-24 00:08:38.513522 | controller -> localhost | SHA256:bqfpcXPv6DkfXMENgbpRMQ+whVJ6XGmfkiRaZOZZW2g zuul-build-sshkey 2025-09-24 00:08:38.513540 | controller -> localhost | The key's randomart image is: 2025-09-24 00:08:38.513558 | controller -> localhost | +---[ECDSA 521]---+ 2025-09-24 00:08:38.513575 | controller -> localhost | | o*oB=+. | 2025-09-24 00:08:38.513592 | controller -> localhost | | .*+*E*...| 2025-09-24 00:08:38.513608 | controller -> localhost | | .+*B.o.+.| 2025-09-24 00:08:38.513624 | controller -> localhost | | ..o o o .| 2025-09-24 00:08:38.513641 | controller -> localhost | | S o . .| 2025-09-24 00:08:38.513658 | controller -> localhost | | . . . . | 2025-09-24 00:08:38.513674 | controller -> localhost | | + + . o | 2025-09-24 00:08:38.513690 | controller -> localhost | | . * o.+ . | 2025-09-24 00:08:38.513706 | controller -> localhost | | .+ .+++ | 2025-09-24 00:08:38.513722 | controller -> localhost | +----[SHA256]-----+ 2025-09-24 00:08:38.513765 | controller -> localhost | ok: Runtime: 0:00:00.009586 2025-09-24 00:08:38.520219 | 2025-09-24 00:08:38.520348 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-09-24 00:08:38.551339 | controller | ok 2025-09-24 00:08:38.561165 | controller | included: /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-09-24 00:08:38.570043 | 2025-09-24 00:08:38.570106 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-09-24 00:08:38.594242 | controller | skipping: Conditional result was False 2025-09-24 00:08:38.600280 | 2025-09-24 00:08:38.600343 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-09-24 00:08:39.058620 | controller | changed 2025-09-24 00:08:39.070999 | 2025-09-24 00:08:39.071189 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-09-24 00:08:39.429087 | controller | ok 2025-09-24 00:08:39.441986 | 2025-09-24 00:08:39.442159 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-09-24 00:08:40.774599 | controller | changed 2025-09-24 00:08:40.789073 | 2025-09-24 00:08:40.789207 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-09-24 00:08:42.142431 | controller | changed 2025-09-24 00:08:42.156099 | 2025-09-24 00:08:42.156297 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-09-24 00:08:42.193913 | controller | skipping: Conditional result was False 2025-09-24 00:08:42.207505 | 2025-09-24 00:08:42.207672 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-09-24 00:08:42.531946 | controller -> localhost | changed 2025-09-24 00:08:42.543002 | 2025-09-24 00:08:42.543156 | TASK [add-build-sshkey : Add back temp key] 2025-09-24 00:08:42.884223 | controller -> localhost | Identity added: /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/work/840fb62e78834f738ae3665b8fcb2278_id_ecdsa (zuul-build-sshkey) 2025-09-24 00:08:42.884517 | controller -> localhost | ok: Runtime: 0:00:00.008948 2025-09-24 00:08:42.891077 | 2025-09-24 00:08:42.891181 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-09-24 00:08:43.229081 | controller | ok 2025-09-24 00:08:43.236181 | 2025-09-24 00:08:43.236293 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-09-24 00:08:43.281853 | controller | skipping: Conditional result was False 2025-09-24 00:08:43.335761 | 2025-09-24 00:08:43.335878 | TASK [include_role : remove-zuul-sshkey] 2025-09-24 00:08:43.359764 | controller | skipping: Conditional result was False 2025-09-24 00:08:43.366160 | 2025-09-24 00:08:43.366230 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-09-24 00:08:43.666785 | controller | ok: "logs" 2025-09-24 00:08:43.667545 | controller | ok: All items complete 2025-09-24 00:08:43.667582 | 2025-09-24 00:08:43.950687 | controller | ok: "artifacts" 2025-09-24 00:08:44.223127 | controller | ok: "docs" 2025-09-24 00:08:44.239374 | 2025-09-24 00:08:44.239493 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-09-24 00:08:44.570166 | controller | changed: "logs" 2025-09-24 00:08:44.897929 | controller | changed: "artifacts" 2025-09-24 00:08:45.194620 | controller | changed: "docs" 2025-09-24 00:08:45.236763 | 2025-09-24 00:08:45.236884 | PLAY RECAP 2025-09-24 00:08:45.236928 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-09-24 00:08:45.236953 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-09-24 00:08:45.236971 | 2025-09-24 00:08:45.417366 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-09-24 00:08:45.418191 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-24 00:08:46.086572 | 2025-09-24 00:08:46.086736 | PLAY [all] 2025-09-24 00:08:46.109034 | 2025-09-24 00:08:46.109180 | TASK [Install binary dependencies] 2025-09-24 00:08:46.190443 | controller | ok 2025-09-24 00:08:46.212279 | 2025-09-24 00:08:46.212543 | TASK [bindep : Include find tasks] 2025-09-24 00:08:46.242052 | controller | ok 2025-09-24 00:08:46.260660 | controller | included: /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-09-24 00:08:46.267006 | 2025-09-24 00:08:46.267096 | TASK [bindep : Look for bindep.txt] 2025-09-24 00:08:46.850407 | controller | ok 2025-09-24 00:08:46.861835 | 2025-09-24 00:08:46.862008 | TASK [bindep : Define bindep_file fact] 2025-09-24 00:08:46.888549 | controller | skipping: Conditional result was False 2025-09-24 00:08:46.902528 | 2025-09-24 00:08:46.902670 | TASK [bindep : Look for other-requirements.txt] 2025-09-24 00:08:47.203065 | controller | ok 2025-09-24 00:08:47.218065 | 2025-09-24 00:08:47.218258 | TASK [bindep : Define bindep_file fact] 2025-09-24 00:08:47.247326 | controller | skipping: Conditional result was False 2025-09-24 00:08:47.257460 | 2025-09-24 00:08:47.257586 | TASK [bindep : Look for bindep fallback file] 2025-09-24 00:08:47.282919 | controller | skipping: Conditional result was False 2025-09-24 00:08:47.292838 | 2025-09-24 00:08:47.292962 | TASK [bindep : Define bindep_file fact] 2025-09-24 00:08:47.319568 | controller | skipping: Conditional result was False 2025-09-24 00:08:47.330101 | 2025-09-24 00:08:47.330231 | TASK [bindep : Include bindep tasks] 2025-09-24 00:08:47.355908 | controller | skipping: Conditional result was False 2025-09-24 00:08:47.369617 | 2025-09-24 00:08:47.369780 | TASK [bindep : Include install tasks] 2025-09-24 00:08:47.395619 | controller | skipping: Conditional result was False 2025-09-24 00:08:47.406065 | 2025-09-24 00:08:47.406202 | LOOP [bindep : Include package tasks] 2025-09-24 00:08:47.472003 | 2025-09-24 00:08:47.472260 | TASK [Run test-setup role] 2025-09-24 00:08:47.496159 | controller | ok 2025-09-24 00:08:47.524104 | 2025-09-24 00:08:47.524226 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-09-24 00:08:47.847425 | controller | ok 2025-09-24 00:08:47.864580 | 2025-09-24 00:08:47.864779 | TASK [test-setup : Run tools/test-setup.sh] 2025-09-24 00:08:48.040864 | controller | skipping: Conditional result was False 2025-09-24 00:08:48.083255 | 2025-09-24 00:08:48.083382 | PLAY RECAP 2025-09-24 00:08:48.083441 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-24 00:08:48.083470 | 2025-09-24 00:08:48.202987 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-09-24 00:08:48.203923 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-24 00:08:48.846346 | 2025-09-24 00:08:48.846506 | PLAY [controller] 2025-09-24 00:08:48.867152 | 2025-09-24 00:08:48.867310 | TASK [Create the /root directory] 2025-09-24 00:08:49.592074 | controller | ok 2025-09-24 00:08:49.603715 | 2025-09-24 00:08:49.604178 | TASK [Install glibc-langpack-en] 2025-09-24 00:08:57.605859 | controller | ok: Nothing to do 2025-09-24 00:08:57.616228 | 2025-09-24 00:08:57.616386 | TASK [Ensure controller directory exists] 2025-09-24 00:08:58.120333 | controller | changed 2025-09-24 00:08:58.132386 | 2025-09-24 00:08:58.132522 | TASK [Install container runtime] 2025-09-24 00:08:58.204669 | controller | ok 2025-09-24 00:08:58.260867 | 2025-09-24 00:08:58.261003 | LOOP [ensure-podman : Find distribution installation] 2025-09-24 00:08:58.311111 | controller | ok: "/var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-09-24 00:08:58.378195 | controller | included: /var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-09-24 00:08:58.394336 | 2025-09-24 00:08:58.394499 | TASK [ensure-podman : Install podman (RedHat)] 2025-09-24 00:10:12.429934 | controller | changed 2025-09-24 00:10:12.437701 | 2025-09-24 00:10:12.437788 | TASK [ensure-podman : Fetch podman version] 2025-09-24 00:10:13.225305 | controller | Client: Podman Engine 2025-09-24 00:10:13.225390 | controller | Version: 4.6.2 2025-09-24 00:10:13.225420 | controller | API Version: 4.6.2 2025-09-24 00:10:13.225447 | controller | Go Version: go1.19.12 2025-09-24 00:10:13.225484 | controller | Built: Mon Aug 28 19:38:31 2023 2025-09-24 00:10:13.225511 | controller | OS/Arch: linux/amd64 2025-09-24 00:10:13.577941 | controller | ok: Runtime: 0:00:00.219398 2025-09-24 00:10:13.584984 | 2025-09-24 00:10:13.585134 | TASK [ensure-podman : Print podman version installed] 2025-09-24 00:10:13.617344 | Podman version: Client: Podman Engine 2025-09-24 00:10:13.617620 | Version: 4.6.2 2025-09-24 00:10:13.617651 | API Version: 4.6.2 2025-09-24 00:10:13.617674 | Go Version: go1.19.12 2025-09-24 00:10:13.617693 | Built: Mon Aug 28 19:38:31 2023 2025-09-24 00:10:13.617713 | OS/Arch: linux/amd64 2025-09-24 00:10:13.623165 | 2025-09-24 00:10:13.623231 | TASK [ensure-podman : Validate podman engine] 2025-09-24 00:10:13.759501 | controller | skipping: Conditional result was False 2025-09-24 00:10:13.768163 | 2025-09-24 00:10:13.768312 | TASK [ensure-podman : Set up docker compatability socket] 2025-09-24 00:10:13.794657 | controller | skipping: Conditional result was False 2025-09-24 00:10:13.810439 | 2025-09-24 00:10:13.810599 | TASK [Ensure python3.8 is present] 2025-09-24 00:10:13.836462 | controller | skipping: Conditional result was False 2025-09-24 00:10:13.844386 | 2025-09-24 00:10:13.844477 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-09-24 00:10:13.867498 | controller | ok 2025-09-24 00:10:13.894250 | 2025-09-24 00:10:13.894394 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-09-24 00:10:17.725080 | controller | ok: Nothing to do 2025-09-24 00:10:17.737661 | 2025-09-24 00:10:17.737802 | TASK [our-ensure-python : Also install python3-devel] 2025-09-24 00:10:30.732336 | controller | changed 2025-09-24 00:10:30.746890 | 2025-09-24 00:10:30.746994 | TASK [Run ensure-virtualenv role] 2025-09-24 00:10:30.766312 | controller | ok 2025-09-24 00:10:30.788382 | 2025-09-24 00:10:30.788535 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-09-24 00:10:31.162717 | controller | /usr/bin/virtualenv 2025-09-24 00:10:31.429077 | controller | ok: Runtime: 0:00:00.003831 2025-09-24 00:10:31.438151 | 2025-09-24 00:10:31.438254 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-09-24 00:10:31.479586 | controller | skipping: Conditional result was False 2025-09-24 00:10:31.480091 | controller | ok: All items complete 2025-09-24 00:10:31.480140 | 2025-09-24 00:10:31.581283 | 2025-09-24 00:10:31.581518 | TASK [Find the full path of the Python interpreter] 2025-09-24 00:10:31.888750 | controller | /usr/bin/python3 2025-09-24 00:10:32.214468 | controller | ok 2025-09-24 00:10:32.227698 | 2025-09-24 00:10:32.227845 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-09-24 00:10:33.611021 | controller | created virtual environment CPython3.11.0.final.0-64 in 737ms 2025-09-24 00:10:33.660342 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-09-24 00:10:33.660393 | controller | seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv) 2025-09-24 00:10:33.660412 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-09-24 00:10:33.660434 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-09-24 00:10:33.881536 | controller | changed 2025-09-24 00:10:33.895146 | 2025-09-24 00:10:33.895285 | TASK [Set selinux package] 2025-09-24 00:10:33.938338 | controller | ok 2025-09-24 00:10:33.951309 | 2025-09-24 00:10:33.951444 | TASK [Set selinux package (Fedora)] 2025-09-24 00:10:33.995069 | controller | ok 2025-09-24 00:10:34.002497 | 2025-09-24 00:10:34.002594 | TASK [Install selinux into virtualenv] 2025-09-24 00:10:36.615452 | controller | Collecting selinux-please-lie-to-me 2025-09-24 00:10:36.707680 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-09-24 00:10:37.235975 | controller | Collecting setuptools<50.0.0 2025-09-24 00:10:37.251138 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-09-24 00:10:37.361614 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 7.6 MB/s eta 0:00:00 2025-09-24 00:10:37.518331 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-09-24 00:10:37.518750 | controller | Attempting uninstall: setuptools 2025-09-24 00:10:37.523628 | controller | Found existing installation: setuptools 62.6.0 2025-09-24 00:10:37.635571 | controller | Uninstalling setuptools-62.6.0: 2025-09-24 00:10:37.650517 | controller | Successfully uninstalled setuptools-62.6.0 2025-09-24 00:10:38.377792 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-09-24 00:10:38.588714 | controller | 2025-09-24 00:10:38.801395 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-24 00:10:38.801449 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-24 00:10:39.197565 | controller | ok: Runtime: 0:00:04.337242 2025-09-24 00:10:39.210305 | 2025-09-24 00:10:39.210474 | TASK [Install pytest-forked into virtualenv] 2025-09-24 00:10:40.438438 | controller | Collecting pytest-forked 2025-09-24 00:10:40.525703 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-09-24 00:10:40.585568 | controller | Collecting py 2025-09-24 00:10:40.597688 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-09-24 00:10:40.634746 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00 2025-09-24 00:10:40.807125 | controller | Collecting pytest>=3.10 2025-09-24 00:10:40.819670 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-09-24 00:10:40.881201 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.2 MB/s eta 0:00:00 2025-09-24 00:10:40.936034 | controller | Collecting iniconfig>=1 2025-09-24 00:10:40.949900 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-09-24 00:10:41.016449 | controller | Collecting packaging>=20 2025-09-24 00:10:41.027935 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-09-24 00:10:41.041870 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.4 MB/s eta 0:00:00 2025-09-24 00:10:41.088248 | controller | Collecting pluggy<2,>=1.5 2025-09-24 00:10:41.100215 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-09-24 00:10:41.173320 | controller | Collecting pygments>=2.7.2 2025-09-24 00:10:41.185328 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-09-24 00:10:41.305558 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.5 MB/s eta 0:00:00 2025-09-24 00:10:41.439938 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-09-24 00:10:43.667946 | 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-24 00:10:43.683767 | controller | 2025-09-24 00:10:43.855079 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-09-24 00:10:43.855124 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-09-24 00:10:44.387597 | controller | ok: Runtime: 0:00:04.148078 2025-09-24 00:10:44.400236 | 2025-09-24 00:10:44.400419 | TASK [Update pip] 2025-09-24 00:10:45.553451 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-09-24 00:10:45.842333 | controller | Collecting pip 2025-09-24 00:10:45.944507 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-09-24 00:10:46.107764 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.0 MB/s eta 0:00:00 2025-09-24 00:10:46.263974 | controller | Installing collected packages: pip 2025-09-24 00:10:46.264304 | controller | Attempting uninstall: pip 2025-09-24 00:10:46.268794 | controller | Found existing installation: pip 22.2.2 2025-09-24 00:10:46.528833 | controller | Uninstalling pip-22.2.2: 2025-09-24 00:10:46.558757 | controller | Successfully uninstalled pip-22.2.2 2025-09-24 00:10:48.336937 | controller | Successfully installed pip-25.2 2025-09-24 00:10:48.587688 | controller | ok: Runtime: 0:00:03.566163 2025-09-24 00:10:48.600648 | 2025-09-24 00:10:48.600807 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-09-24 00:10:49.122864 | controller | changed 2025-09-24 00:10:49.135317 | 2025-09-24 00:10:49.135487 | TASK [Install ansible into virtualenv] 2025-09-24 00:10:50.224832 | controller | Processing ./src/github.com/ansible/ansible 2025-09-24 00:10:50.231192 | controller | Installing build dependencies: started 2025-09-24 00:10:52.112435 | controller | Installing build dependencies: finished with status 'done' 2025-09-24 00:10:53.608338 | controller | Getting requirements to build wheel: started 2025-09-24 00:10:53.608415 | controller | Getting requirements to build wheel: finished with status 'done' 2025-09-24 00:10:53.610104 | controller | Preparing metadata (pyproject.toml): started 2025-09-24 00:10:54.517351 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-09-24 00:10:54.522297 | 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-24 00:10:54.527074 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-09-24 00:10:54.815728 | controller | ERROR 2025-09-24 00:10:54.816009 | controller | { 2025-09-24 00:10:54.816072 | controller | "delta": "0:00:05.062668", 2025-09-24 00:10:54.816095 | controller | "end": "2025-09-24 00:10:54.671253", 2025-09-24 00:10:54.816115 | controller | "msg": "non-zero return code", 2025-09-24 00:10:54.816147 | controller | "rc": 1, 2025-09-24 00:10:54.816167 | controller | "start": "2025-09-24 00:10:49.608585" 2025-09-24 00:10:54.816185 | controller | } failure 2025-09-24 00:10:54.818453 | 2025-09-24 00:10:54.818512 | PLAY RECAP 2025-09-24 00:10:54.818562 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-09-24 00:10:54.818587 | 2025-09-24 00:10:54.948638 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-09-24 00:10:54.950957 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-24 00:10:55.525306 | 2025-09-24 00:10:55.525414 | PLAY [all] 2025-09-24 00:10:55.547401 | 2025-09-24 00:10:55.547496 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-09-24 00:10:56.331138 | controller | changed: non-zero return code 2025-09-24 00:10:56.343790 | 2025-09-24 00:10:56.343959 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-09-24 00:10:56.362300 | controller | skipping: Conditional result was False 2025-09-24 00:10:56.375705 | 2025-09-24 00:10:56.375882 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-09-24 00:10:56.417880 | 2025-09-24 00:10:56.418162 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-09-24 00:10:56.460969 | 2025-09-24 00:10:56.461533 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-09-24 00:10:56.489865 | controller | skipping: Conditional result was False 2025-09-24 00:10:56.503000 | 2025-09-24 00:10:56.503191 | LOOP [fetch-subunit-output : Generate subunit file] 2025-09-24 00:10:56.545917 | 2025-09-24 00:10:56.546221 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-09-24 00:10:56.572397 | controller | skipping: Conditional result was False 2025-09-24 00:10:56.578947 | 2025-09-24 00:10:56.579032 | TASK [fetch-subunit-output : Remove the temporary file] 2025-09-24 00:10:56.602938 | controller | skipping: Conditional result was False 2025-09-24 00:10:56.610083 | 2025-09-24 00:10:56.610164 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-09-24 00:10:56.637058 | controller | skipping: Conditional result was False 2025-09-24 00:10:56.662411 | 2025-09-24 00:10:56.662472 | PLAY RECAP 2025-09-24 00:10:56.662512 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-09-24 00:10:56.662532 | 2025-09-24 00:10:56.753581 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-09-24 00:10:56.754502 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-09-24 00:10:57.416256 | 2025-09-24 00:10:57.416401 | PLAY [all:!appliance*] 2025-09-24 00:10:57.439843 | 2025-09-24 00:10:57.439987 | TASK [unregister the node] 2025-09-24 00:10:57.582339 | controller | skipping: Conditional result was False 2025-09-24 00:10:57.591052 | 2025-09-24 00:10:57.591167 | TASK [include_role : fetch-output] 2025-09-24 00:10:57.623159 | controller | ok 2025-09-24 00:10:57.647025 | 2025-09-24 00:10:57.647157 | TASK [fetch-output : Set log path for multiple nodes] 2025-09-24 00:10:57.691866 | controller | skipping: Conditional result was False 2025-09-24 00:10:57.698264 | 2025-09-24 00:10:57.698352 | TASK [fetch-output : Set log path for single node] 2025-09-24 00:10:57.727980 | controller | ok 2025-09-24 00:10:57.733284 | 2025-09-24 00:10:57.733360 | LOOP [fetch-output : Ensure local output dirs] 2025-09-24 00:10:58.112175 | controller -> localhost | ok: "/var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/work/logs" 2025-09-24 00:10:58.387827 | controller -> localhost | changed: "/var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/work/artifacts" 2025-09-24 00:10:58.652648 | controller -> localhost | changed: "/var/lib/zuul/builds/840fb62e78834f738ae3665b8fcb2278/work/docs" 2025-09-24 00:10:58.663248 | 2025-09-24 00:10:58.663390 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-09-24 00:10:59.898792 | controller | changed: 2025-09-24 00:10:59.899074 | controller | .d..t...... ./ 2025-09-24 00:10:59.899105 | controller | cd+++++++++ controller/ 2025-09-24 00:10:59.899142 | controller | changed: All items complete 2025-09-24 00:10:59.899162 | 2025-09-24 00:11:00.937056 | controller | changed: .d..t...... ./ 2025-09-24 00:11:02.016956 | controller | changed: .d..t...... ./ 2025-09-24 00:11:02.043569 | 2025-09-24 00:11:02.043761 | TASK [include_role : fetch-output-openshift] 2025-09-24 00:11:02.069623 | controller | skipping: Conditional result was False 2025-09-24 00:11:02.082804 | 2025-09-24 00:11:02.082943 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-09-24 00:11:02.131900 | controller | skipping: Conditional result was False 2025-09-24 00:11:02.146843 | controller | skipping: Conditional result was False 2025-09-24 00:11:02.198492 | 2025-09-24 00:11:02.198875 | PLAY [localhost] 2025-09-24 00:11:02.215901 | 2025-09-24 00:11:02.216112 | TASK [Run Zuul manifest role] 2025-09-24 00:11:02.238194 | localhost | ok 2025-09-24 00:11:02.259001 | 2025-09-24 00:11:02.259393 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-09-24 00:11:02.678707 | localhost | changed 2025-09-24 00:11:02.684726 | 2025-09-24 00:11:02.684844 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-09-24 00:11:02.717250 | localhost | ok 2025-09-24 00:11:02.725399 | 2025-09-24 00:11:02.725466 | TASK [Set zuul-log-path fact] 2025-09-24 00:11:02.744314 | localhost | ok 2025-09-24 00:11:02.757676 | 2025-09-24 00:11:02.757750 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-09-24 00:11:02.787230 | localhost | ok 2025-09-24 00:11:02.799566 | 2025-09-24 00:11:02.799646 | LOOP [Run upload-logs-swift role] 2025-09-24 00:11:02.824448 | localhost | Output suppressed because no_log was given 2025-09-24 00:11:02.858300 | 2025-09-24 00:11:02.858382 | TASK [Set zuul-log-path fact] 2025-09-24 00:11:02.883584 | localhost | skipping: Conditional result was False 2025-09-24 00:11:02.888503 | 2025-09-24 00:11:02.888576 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-09-24 00:11:03.373185 | localhost -> localhost | ok: Runtime: 0:00:00.006694 2025-09-24 00:11:03.381002 | 2025-09-24 00:11:03.381169 | TASK [upload-logs-swift : Upload logs to swift]