2025-10-02 00:17:44.587292 | Job console starting... 2025-10-02 00:17:44.596470 | Updating repositories 2025-10-02 00:17:44.753362 | Preparing job workspace 2025-10-02 00:17:48.458250 | Running Ansible setup... 2025-10-02 00:17:56.722405 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-02 00:17:57.316676 | 2025-10-02 00:17:57.316792 | PLAY [localhost] 2025-10-02 00:17:57.324910 | 2025-10-02 00:17:57.324979 | TASK [Gathering Facts] 2025-10-02 00:17:58.338779 | localhost | ok 2025-10-02 00:17:58.357838 | 2025-10-02 00:17:58.357961 | TASK [Setup log path fact] 2025-10-02 00:17:58.378579 | localhost | ok 2025-10-02 00:17:58.394839 | 2025-10-02 00:17:58.394932 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-02 00:17:58.436847 | localhost | ok 2025-10-02 00:17:58.452581 | 2025-10-02 00:17:58.452700 | TASK [emit-job-header : Print job information] 2025-10-02 00:17:58.505626 | # Job Information 2025-10-02 00:17:58.505889 | Ansible Version: 2.15.12 2025-10-02 00:17:58.505957 | Job: ansible-test-sanity-docker-devel 2025-10-02 00:17:58.506000 | Pipeline: periodic 2025-10-02 00:17:58.506040 | Executor: ze02.softwarefactory-project.io 2025-10-02 00:17:58.506082 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-02 00:17:58.506126 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/d2e/ansible/d2e20e30441a4043be190fe3edaf537b/ 2025-10-02 00:17:58.506166 | Event ID: dc6de0c9c3c649899b29042e956f2ac8 2025-10-02 00:17:58.513940 | 2025-10-02 00:17:58.514071 | LOOP [emit-job-header : Print node information] 2025-10-02 00:17:58.637032 | localhost | ok: 2025-10-02 00:17:58.637328 | localhost | # Node Information 2025-10-02 00:17:58.637387 | localhost | Inventory Hostname: controller 2025-10-02 00:17:58.637429 | localhost | Hostname: np0005465392 2025-10-02 00:17:58.637470 | localhost | Username: zuul 2025-10-02 00:17:58.637516 | localhost | Distro: Fedora 37 2025-10-02 00:17:58.637555 | localhost | Provider: ansible-vexxhost-ams1 2025-10-02 00:17:58.637592 | localhost | Region: ams1 2025-10-02 00:17:58.637628 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-02 00:17:58.637709 | localhost | Product Name: OpenStack Nova 2025-10-02 00:17:58.637753 | localhost | Interface IP: 38.129.16.150 2025-10-02 00:17:58.658939 | 2025-10-02 00:17:58.659118 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-02 00:17:59.113057 | localhost -> localhost | changed 2025-10-02 00:17:59.124941 | 2025-10-02 00:17:59.125072 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-02 00:18:00.030019 | localhost -> localhost | changed 2025-10-02 00:18:00.049493 | 2025-10-02 00:18:00.049557 | PLAY [all:!appliance*] 2025-10-02 00:18:00.065070 | 2025-10-02 00:18:00.065135 | TASK [include_role : start-zuul-console] 2025-10-02 00:18:00.084575 | controller | ok 2025-10-02 00:18:00.097978 | 2025-10-02 00:18:00.098042 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-02 00:18:01.140141 | controller | ok 2025-10-02 00:18:01.164631 | 2025-10-02 00:18:01.164834 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-02 00:18:03.758466 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-02 00:18:03.774377 | 2025-10-02 00:18:03.774551 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-02 00:18:04.148959 | controller | skipping: Conditional result was False 2025-10-02 00:18:04.162812 | 2025-10-02 00:18:04.162973 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-02 00:18:04.191424 | controller | skipping: Conditional result was False 2025-10-02 00:18:04.207448 | 2025-10-02 00:18:04.207646 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-02 00:18:04.234944 | controller | skipping: Conditional result was False 2025-10-02 00:18:04.244512 | 2025-10-02 00:18:04.244621 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-02 00:18:04.280514 | controller | skipping: Conditional result was False 2025-10-02 00:18:04.290491 | 2025-10-02 00:18:04.290624 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-02 00:18:04.316068 | controller | skipping: Conditional result was False 2025-10-02 00:18:04.325624 | 2025-10-02 00:18:04.325766 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-02 00:18:04.351913 | controller | skipping: Conditional result was False 2025-10-02 00:18:04.369034 | 2025-10-02 00:18:04.369182 | TASK [Disable Fedora Modular] 2025-10-02 00:18:05.639748 | controller | changed 2025-10-02 00:18:05.653900 | 2025-10-02 00:18:05.654034 | TASK [Enable EPEL] 2025-10-02 00:18:05.681506 | controller | skipping: Conditional result was False 2025-10-02 00:18:05.694399 | 2025-10-02 00:18:05.694529 | TASK [Register the RHEL node] 2025-10-02 00:18:06.112754 | 2025-10-02 00:18:06.113028 | TASK [Show the subscription-manager status] 2025-10-02 00:18:06.506720 | controller | skipping: Conditional result was False 2025-10-02 00:18:06.522523 | 2025-10-02 00:18:06.522724 | TASK [Enable EPEL on RHEL] 2025-10-02 00:18:06.910056 | controller | skipping: Conditional result was False 2025-10-02 00:18:06.926273 | 2025-10-02 00:18:06.926414 | TASK [Install git and tox] 2025-10-02 00:20:28.424409 | controller | changed 2025-10-02 00:20:28.438237 | 2025-10-02 00:20:28.438368 | TASK [include_role : prepare-workspace] 2025-10-02 00:20:28.476371 | controller | ok 2025-10-02 00:20:28.512741 | 2025-10-02 00:20:28.512846 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-02 00:20:29.382353 | controller | ok 2025-10-02 00:20:29.395790 | 2025-10-02 00:20:29.395924 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-02 00:20:46.036067 | controller | Output suppressed because no_log was given 2025-10-02 00:20:46.046095 | 2025-10-02 00:20:46.046171 | TASK [include_role : prepare-workspace-openshift] 2025-10-02 00:20:46.070811 | controller | skipping: Conditional result was False 2025-10-02 00:20:46.092167 | 2025-10-02 00:20:46.092234 | PLAY [all:!appliance] 2025-10-02 00:20:46.107055 | 2025-10-02 00:20:46.107130 | TASK [Run add-build-sshkey role (RSA)] 2025-10-02 00:20:46.137921 | controller | ok 2025-10-02 00:20:46.153077 | 2025-10-02 00:20:46.153167 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-02 00:20:46.401965 | controller -> localhost | ok 2025-10-02 00:20:46.415769 | 2025-10-02 00:20:46.415941 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-02 00:20:46.446006 | controller | ok 2025-10-02 00:20:46.478819 | controller | included: /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-02 00:20:46.489953 | 2025-10-02 00:20:46.490037 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-02 00:20:46.962144 | controller -> localhost | Generating public/private rsa key pair. 2025-10-02 00:20:46.962321 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/work/d2e20e30441a4043be190fe3edaf537b_id_rsa. 2025-10-02 00:20:46.962350 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/work/d2e20e30441a4043be190fe3edaf537b_id_rsa.pub. 2025-10-02 00:20:46.962371 | controller -> localhost | The key fingerprint is: 2025-10-02 00:20:46.962390 | controller -> localhost | SHA256:6f0mHMBTdqjEL7fuGMPZMfG8sl81uNS3hIc93BPzw3w zuul-build-sshkey 2025-10-02 00:20:46.962409 | controller -> localhost | The key's randomart image is: 2025-10-02 00:20:46.962427 | controller -> localhost | +---[RSA 2048]----+ 2025-10-02 00:20:46.962444 | controller -> localhost | | . . | 2025-10-02 00:20:46.962465 | controller -> localhost | | o + . | 2025-10-02 00:20:46.962483 | controller -> localhost | | o =.. o | 2025-10-02 00:20:46.962501 | controller -> localhost | | *.o+ X =| 2025-10-02 00:20:46.962518 | controller -> localhost | | S=o.o= &E| 2025-10-02 00:20:46.962545 | controller -> localhost | | o +oo..+.O| 2025-10-02 00:20:46.962572 | controller -> localhost | | *o+..... | 2025-10-02 00:20:46.962600 | controller -> localhost | | +++.. | 2025-10-02 00:20:46.962627 | controller -> localhost | | ..o+o | 2025-10-02 00:20:46.962651 | controller -> localhost | +----[SHA256]-----+ 2025-10-02 00:20:46.962724 | controller -> localhost | ok: Runtime: 0:00:00.122397 2025-10-02 00:20:46.969280 | 2025-10-02 00:20:46.969342 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-02 00:20:47.008589 | controller | ok 2025-10-02 00:20:47.019001 | controller | included: /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-02 00:20:47.027504 | 2025-10-02 00:20:47.027568 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-02 00:20:47.051752 | controller | skipping: Conditional result was False 2025-10-02 00:20:47.062629 | 2025-10-02 00:20:47.062797 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-02 00:20:48.139612 | controller | changed 2025-10-02 00:20:48.153522 | 2025-10-02 00:20:48.153727 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-02 00:20:48.880583 | controller | ok 2025-10-02 00:20:48.894090 | 2025-10-02 00:20:48.894256 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-02 00:20:51.924879 | controller | changed 2025-10-02 00:20:51.930429 | 2025-10-02 00:20:51.930490 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-02 00:20:54.989410 | controller | changed 2025-10-02 00:20:55.002509 | 2025-10-02 00:20:55.002702 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-02 00:20:55.020346 | controller | skipping: Conditional result was False 2025-10-02 00:20:55.034625 | 2025-10-02 00:20:55.034819 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-02 00:20:55.428787 | controller -> localhost | changed 2025-10-02 00:20:55.445592 | 2025-10-02 00:20:55.445703 | TASK [add-build-sshkey : Add back temp key] 2025-10-02 00:20:55.715367 | controller -> localhost | Identity added: /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/work/d2e20e30441a4043be190fe3edaf537b_id_rsa (zuul-build-sshkey) 2025-10-02 00:20:55.715770 | controller -> localhost | ok: Runtime: 0:00:00.014082 2025-10-02 00:20:55.730287 | 2025-10-02 00:20:55.730578 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-02 00:20:56.639192 | controller | ok 2025-10-02 00:20:56.650782 | 2025-10-02 00:20:56.650890 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-02 00:20:56.689002 | controller | skipping: Conditional result was False 2025-10-02 00:20:56.705814 | 2025-10-02 00:20:56.705906 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-02 00:20:56.738740 | controller | ok 2025-10-02 00:20:56.761472 | 2025-10-02 00:20:56.761572 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-02 00:20:57.051373 | controller -> localhost | ok 2025-10-02 00:20:57.065404 | 2025-10-02 00:20:57.065544 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-02 00:20:57.105491 | controller | ok 2025-10-02 00:20:57.127685 | controller | included: /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-02 00:20:57.135976 | 2025-10-02 00:20:57.136060 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-02 00:20:57.486974 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-02 00:20:57.487294 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/work/d2e20e30441a4043be190fe3edaf537b_id_ecdsa. 2025-10-02 00:20:57.487353 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/work/d2e20e30441a4043be190fe3edaf537b_id_ecdsa.pub. 2025-10-02 00:20:57.487412 | controller -> localhost | The key fingerprint is: 2025-10-02 00:20:57.487455 | controller -> localhost | SHA256:KOZneHFmGLzBmbv98NVwFBHgQ/EKdpJhy+fYLgu1hZ0 zuul-build-sshkey 2025-10-02 00:20:57.487495 | controller -> localhost | The key's randomart image is: 2025-10-02 00:20:57.487534 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-02 00:20:57.487572 | controller -> localhost | | o +o+o | 2025-10-02 00:20:57.487610 | controller -> localhost | | o o o * . . | 2025-10-02 00:20:57.487647 | controller -> localhost | | B B = o | 2025-10-02 00:20:57.487750 | controller -> localhost | | B . @ = | 2025-10-02 00:20:57.487792 | controller -> localhost | | o * S + E . | 2025-10-02 00:20:57.487829 | controller -> localhost | | o o B . + + | 2025-10-02 00:20:57.487866 | controller -> localhost | | o = + o o . | 2025-10-02 00:20:57.487902 | controller -> localhost | | + = + | 2025-10-02 00:20:57.487938 | controller -> localhost | | + | 2025-10-02 00:20:57.487974 | controller -> localhost | +----[SHA256]-----+ 2025-10-02 00:20:57.488067 | controller -> localhost | ok: Runtime: 0:00:00.011178 2025-10-02 00:20:57.501605 | 2025-10-02 00:20:57.501767 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-02 00:20:57.540745 | controller | ok 2025-10-02 00:20:57.556932 | controller | included: /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-02 00:20:57.601241 | 2025-10-02 00:20:57.601373 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-02 00:20:57.625352 | controller | skipping: Conditional result was False 2025-10-02 00:20:57.631978 | 2025-10-02 00:20:57.632041 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-02 00:20:58.576064 | controller | changed 2025-10-02 00:20:58.589202 | 2025-10-02 00:20:58.589336 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-02 00:20:59.284335 | controller | ok 2025-10-02 00:20:59.297131 | 2025-10-02 00:20:59.297271 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-02 00:21:02.374640 | controller | changed 2025-10-02 00:21:02.386806 | 2025-10-02 00:21:02.386941 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-02 00:21:05.511474 | controller | changed 2025-10-02 00:21:05.525493 | 2025-10-02 00:21:05.525642 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-02 00:21:05.554738 | controller | skipping: Conditional result was False 2025-10-02 00:21:05.574780 | 2025-10-02 00:21:05.575014 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-02 00:21:05.859283 | controller -> localhost | changed 2025-10-02 00:21:05.884785 | 2025-10-02 00:21:05.884953 | TASK [add-build-sshkey : Add back temp key] 2025-10-02 00:21:06.196129 | controller -> localhost | Identity added: /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/work/d2e20e30441a4043be190fe3edaf537b_id_ecdsa (zuul-build-sshkey) 2025-10-02 00:21:06.196407 | controller -> localhost | ok: Runtime: 0:00:00.013026 2025-10-02 00:21:06.210479 | 2025-10-02 00:21:06.210724 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-02 00:21:06.994617 | controller | ok 2025-10-02 00:21:07.006634 | 2025-10-02 00:21:07.006799 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-02 00:21:07.064281 | controller | skipping: Conditional result was False 2025-10-02 00:21:07.090025 | 2025-10-02 00:21:07.090190 | TASK [include_role : remove-zuul-sshkey] 2025-10-02 00:21:07.116695 | controller | skipping: Conditional result was False 2025-10-02 00:21:07.130016 | 2025-10-02 00:21:07.130168 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-02 00:21:07.828610 | controller | ok: "logs" 2025-10-02 00:21:07.829044 | controller | ok: All items complete 2025-10-02 00:21:07.829112 | 2025-10-02 00:21:08.466612 | controller | ok: "artifacts" 2025-10-02 00:21:09.116152 | controller | ok: "docs" 2025-10-02 00:21:09.136152 | 2025-10-02 00:21:09.136310 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-02 00:21:09.846412 | controller | changed: "logs" 2025-10-02 00:21:10.494182 | controller | changed: "artifacts" 2025-10-02 00:21:11.131487 | controller | changed: "docs" 2025-10-02 00:21:11.191856 | 2025-10-02 00:21:11.191974 | PLAY RECAP 2025-10-02 00:21:11.192030 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-02 00:21:11.192066 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-02 00:21:11.192090 | 2025-10-02 00:21:11.304955 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-02 00:21:11.306598 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-02 00:21:11.920320 | 2025-10-02 00:21:11.920428 | PLAY [all] 2025-10-02 00:21:11.943232 | 2025-10-02 00:21:11.943332 | TASK [Install binary dependencies] 2025-10-02 00:21:12.013153 | controller | ok 2025-10-02 00:21:12.044102 | 2025-10-02 00:21:12.044272 | TASK [bindep : Include find tasks] 2025-10-02 00:21:12.087510 | controller | ok 2025-10-02 00:21:12.105585 | controller | included: /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-02 00:21:12.120025 | 2025-10-02 00:21:12.120174 | TASK [bindep : Look for bindep.txt] 2025-10-02 00:21:13.068257 | controller | ok 2025-10-02 00:21:13.080910 | 2025-10-02 00:21:13.081056 | TASK [bindep : Define bindep_file fact] 2025-10-02 00:21:13.108220 | controller | skipping: Conditional result was False 2025-10-02 00:21:13.121175 | 2025-10-02 00:21:13.121316 | TASK [bindep : Look for other-requirements.txt] 2025-10-02 00:21:13.753100 | controller | ok 2025-10-02 00:21:13.766521 | 2025-10-02 00:21:13.766691 | TASK [bindep : Define bindep_file fact] 2025-10-02 00:21:13.804151 | controller | skipping: Conditional result was False 2025-10-02 00:21:13.817905 | 2025-10-02 00:21:13.818235 | TASK [bindep : Look for bindep fallback file] 2025-10-02 00:21:13.866048 | controller | skipping: Conditional result was False 2025-10-02 00:21:13.875800 | 2025-10-02 00:21:13.875904 | TASK [bindep : Define bindep_file fact] 2025-10-02 00:21:13.911876 | controller | skipping: Conditional result was False 2025-10-02 00:21:13.921097 | 2025-10-02 00:21:13.921192 | TASK [bindep : Include bindep tasks] 2025-10-02 00:21:13.956930 | controller | skipping: Conditional result was False 2025-10-02 00:21:13.966459 | 2025-10-02 00:21:13.966550 | TASK [bindep : Include install tasks] 2025-10-02 00:21:14.005959 | controller | skipping: Conditional result was False 2025-10-02 00:21:14.019811 | 2025-10-02 00:21:14.019956 | LOOP [bindep : Include package tasks] 2025-10-02 00:21:14.110538 | 2025-10-02 00:21:14.110721 | TASK [Run test-setup role] 2025-10-02 00:21:14.129161 | controller | ok 2025-10-02 00:21:14.150809 | 2025-10-02 00:21:14.150917 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-02 00:21:14.909845 | controller | ok 2025-10-02 00:21:14.923147 | 2025-10-02 00:21:14.923315 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-02 00:21:15.301214 | controller | skipping: Conditional result was False 2025-10-02 00:21:15.356658 | 2025-10-02 00:21:15.356825 | PLAY RECAP 2025-10-02 00:21:15.356913 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-02 00:21:15.357064 | 2025-10-02 00:21:15.461292 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-02 00:21:15.463086 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-02 00:21:16.069919 | 2025-10-02 00:21:16.070038 | PLAY [controller] 2025-10-02 00:21:16.089855 | 2025-10-02 00:21:16.089930 | TASK [Create the /root directory] 2025-10-02 00:21:17.157211 | controller | ok 2025-10-02 00:21:17.171986 | 2025-10-02 00:21:17.172214 | TASK [Install glibc-langpack-en] 2025-10-02 00:21:26.217325 | controller | ok: Nothing to do 2025-10-02 00:21:26.229656 | 2025-10-02 00:21:26.229868 | TASK [Ensure controller directory exists] 2025-10-02 00:21:27.058048 | controller | changed 2025-10-02 00:21:27.070562 | 2025-10-02 00:21:27.070756 | TASK [Install container runtime] 2025-10-02 00:21:27.151791 | controller | ok 2025-10-02 00:21:27.217784 | 2025-10-02 00:21:27.217929 | LOOP [ensure-podman : Find distribution installation] 2025-10-02 00:21:27.247381 | controller | ok: "/var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-02 00:21:27.266179 | controller | included: /var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-02 00:21:27.276067 | 2025-10-02 00:21:27.276184 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-02 00:23:30.549347 | controller | changed 2025-10-02 00:23:30.565061 | 2025-10-02 00:23:30.565216 | TASK [ensure-podman : Fetch podman version] 2025-10-02 00:23:31.744102 | controller | Client: Podman Engine 2025-10-02 00:23:31.779439 | controller | Version: 4.6.2 2025-10-02 00:23:31.779493 | controller | API Version: 4.6.2 2025-10-02 00:23:31.779502 | controller | Go Version: go1.19.12 2025-10-02 00:23:31.779649 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-02 00:23:31.779664 | controller | OS/Arch: linux/amd64 2025-10-02 00:23:31.945082 | controller | ok: Runtime: 0:00:00.307631 2025-10-02 00:23:31.958736 | 2025-10-02 00:23:31.958881 | TASK [ensure-podman : Print podman version installed] 2025-10-02 00:23:32.008097 | Podman version: Client: Podman Engine 2025-10-02 00:23:32.008334 | Version: 4.6.2 2025-10-02 00:23:32.008395 | API Version: 4.6.2 2025-10-02 00:23:32.008439 | Go Version: go1.19.12 2025-10-02 00:23:32.008479 | Built: Mon Aug 28 19:38:31 2023 2025-10-02 00:23:32.008519 | OS/Arch: linux/amd64 2025-10-02 00:23:32.020472 | 2025-10-02 00:23:32.020605 | TASK [ensure-podman : Validate podman engine] 2025-10-02 00:23:32.391370 | controller | skipping: Conditional result was False 2025-10-02 00:23:32.405317 | 2025-10-02 00:23:32.405456 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-02 00:23:32.432074 | controller | skipping: Conditional result was False 2025-10-02 00:23:32.458164 | 2025-10-02 00:23:32.458325 | TASK [Ensure python3.8 is present] 2025-10-02 00:23:32.487121 | controller | skipping: Conditional result was False 2025-10-02 00:23:32.501081 | 2025-10-02 00:23:32.501212 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-02 00:23:32.534576 | controller | ok 2025-10-02 00:23:32.565947 | 2025-10-02 00:23:32.566113 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-02 00:23:36.529579 | controller | ok: Nothing to do 2025-10-02 00:23:36.542022 | 2025-10-02 00:23:36.542148 | TASK [our-ensure-python : Also install python3-devel] 2025-10-02 00:23:51.851941 | controller | changed 2025-10-02 00:23:51.863984 | 2025-10-02 00:23:51.864063 | TASK [Run ensure-virtualenv role] 2025-10-02 00:23:51.883605 | controller | ok 2025-10-02 00:23:51.903691 | 2025-10-02 00:23:51.903757 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-02 00:23:52.694808 | controller | /usr/bin/virtualenv 2025-10-02 00:23:53.284150 | controller | ok: Runtime: 0:00:00.005786 2025-10-02 00:23:53.299311 | 2025-10-02 00:23:53.299463 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-02 00:23:53.324839 | controller | skipping: Conditional result was False 2025-10-02 00:23:53.325249 | controller | ok: All items complete 2025-10-02 00:23:53.325289 | 2025-10-02 00:23:53.356188 | 2025-10-02 00:23:53.356380 | TASK [Find the full path of the Python interpreter] 2025-10-02 00:23:54.180055 | controller | /usr/bin/python3 2025-10-02 00:23:54.728454 | controller | ok 2025-10-02 00:23:54.741268 | 2025-10-02 00:23:54.741872 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-02 00:23:56.539175 | controller | created virtual environment CPython3.11.0.final.0-64 in 823ms 2025-10-02 00:23:56.633871 | controller | creator CPython3Posix(dest=/home/zuul/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-02 00:23:56.633926 | 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-10-02 00:23:56.633941 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-02 00:23:56.633961 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-02 00:23:57.112427 | controller | changed 2025-10-02 00:23:57.127058 | 2025-10-02 00:23:57.127195 | TASK [Set selinux package] 2025-10-02 00:23:57.169482 | controller | ok 2025-10-02 00:23:57.181432 | 2025-10-02 00:23:57.181564 | TASK [Set selinux package (Fedora)] 2025-10-02 00:23:57.242251 | controller | ok 2025-10-02 00:23:57.253760 | 2025-10-02 00:23:57.253893 | TASK [Install selinux into virtualenv] 2025-10-02 00:24:00.595044 | controller | Collecting selinux-please-lie-to-me 2025-10-02 00:24:00.739807 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-02 00:24:01.267475 | controller | Collecting setuptools<50.0.0 2025-10-02 00:24:01.272572 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-02 00:24:01.325167 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 16.7 MB/s eta 0:00:00 2025-10-02 00:24:01.464356 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-02 00:24:01.464567 | controller | Attempting uninstall: setuptools 2025-10-02 00:24:01.468914 | controller | Found existing installation: setuptools 62.6.0 2025-10-02 00:24:01.571602 | controller | Uninstalling setuptools-62.6.0: 2025-10-02 00:24:01.586283 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-02 00:24:02.426695 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-02 00:24:02.686757 | controller | 2025-10-02 00:24:03.113977 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-02 00:24:03.114036 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-02 00:24:03.667212 | controller | ok: Runtime: 0:00:05.011287 2025-10-02 00:24:03.680554 | 2025-10-02 00:24:03.680760 | TASK [Install pytest-forked into virtualenv] 2025-10-02 00:24:05.495000 | controller | Collecting pytest-forked 2025-10-02 00:24:05.569158 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-02 00:24:05.667914 | controller | Collecting py 2025-10-02 00:24:05.679710 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-02 00:24:05.718879 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.6 MB/s eta 0:00:00 2025-10-02 00:24:05.933671 | controller | Collecting pytest>=3.10 2025-10-02 00:24:05.945787 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-02 00:24:05.976056 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 13.4 MB/s eta 0:00:00 2025-10-02 00:24:06.056063 | controller | Collecting iniconfig>=1 2025-10-02 00:24:06.065268 | controller | Downloading iniconfig-2.1.0-py3-none-any.whl (6.0 kB) 2025-10-02 00:24:06.164649 | controller | Collecting packaging>=20 2025-10-02 00:24:06.168911 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-02 00:24:06.185707 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.1 MB/s eta 0:00:00 2025-10-02 00:24:06.261987 | controller | Collecting pluggy<2,>=1.5 2025-10-02 00:24:06.273227 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-02 00:24:06.398714 | controller | Collecting pygments>=2.7.2 2025-10-02 00:24:06.402604 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-02 00:24:06.441050 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 37.8 MB/s eta 0:00:00 2025-10-02 00:24:06.568823 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-02 00:24:08.981409 | 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-10-02 00:24:08.999924 | controller | 2025-10-02 00:24:09.264367 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-02 00:24:09.264421 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-02 00:24:09.590825 | controller | ok: Runtime: 0:00:04.674421 2025-10-02 00:24:09.599372 | 2025-10-02 00:24:09.599464 | TASK [Update pip] 2025-10-02 00:24:11.136168 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-02 00:24:11.422600 | controller | Collecting pip 2025-10-02 00:24:11.502091 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-02 00:24:11.592428 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 20.9 MB/s eta 0:00:00 2025-10-02 00:24:11.720233 | controller | Installing collected packages: pip 2025-10-02 00:24:11.720439 | controller | Attempting uninstall: pip 2025-10-02 00:24:11.723831 | controller | Found existing installation: pip 22.2.2 2025-10-02 00:24:11.965179 | controller | Uninstalling pip-22.2.2: 2025-10-02 00:24:11.997853 | controller | Successfully uninstalled pip-22.2.2 2025-10-02 00:24:13.991708 | controller | Successfully installed pip-25.2 2025-10-02 00:24:14.523350 | controller | ok: Runtime: 0:00:03.746146 2025-10-02 00:24:14.536433 | 2025-10-02 00:24:14.536575 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-02 00:24:15.507517 | controller | changed 2025-10-02 00:24:15.519305 | 2025-10-02 00:24:15.519434 | TASK [Install ansible into virtualenv] 2025-10-02 00:24:16.872798 | controller | Processing ./src/github.com/ansible/ansible 2025-10-02 00:24:16.880328 | controller | Installing build dependencies: started 2025-10-02 00:24:18.921158 | controller | Installing build dependencies: finished with status 'done' 2025-10-02 00:24:20.786666 | controller | Getting requirements to build wheel: started 2025-10-02 00:24:20.786732 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-02 00:24:20.786748 | controller | Preparing metadata (pyproject.toml): started 2025-10-02 00:24:21.874749 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-02 00:24:21.878751 | 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-10-02 00:24:21.886453 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-02 00:24:22.476609 | controller | ERROR 2025-10-02 00:24:22.477072 | controller | { 2025-10-02 00:24:22.477138 | controller | "delta": "0:00:05.861248", 2025-10-02 00:24:22.477182 | controller | "end": "2025-10-02 00:24:22.098000", 2025-10-02 00:24:22.477222 | controller | "msg": "non-zero return code", 2025-10-02 00:24:22.477285 | controller | "rc": 1, 2025-10-02 00:24:22.477322 | controller | "start": "2025-10-02 00:24:16.236752" 2025-10-02 00:24:22.477358 | controller | } failure 2025-10-02 00:24:22.481141 | 2025-10-02 00:24:22.481274 | PLAY RECAP 2025-10-02 00:24:22.481396 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-02 00:24:22.481451 | 2025-10-02 00:24:22.657733 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-02 00:24:22.660458 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-02 00:24:23.281073 | 2025-10-02 00:24:23.281246 | PLAY [all] 2025-10-02 00:24:23.303941 | 2025-10-02 00:24:23.304052 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-02 00:24:25.160504 | controller | changed: non-zero return code 2025-10-02 00:24:25.166930 | 2025-10-02 00:24:25.167011 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-02 00:24:25.181160 | controller | skipping: Conditional result was False 2025-10-02 00:24:25.188344 | 2025-10-02 00:24:25.188421 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-02 00:24:25.220106 | 2025-10-02 00:24:25.220273 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-02 00:24:25.251279 | 2025-10-02 00:24:25.251468 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-02 00:24:25.275395 | controller | skipping: Conditional result was False 2025-10-02 00:24:25.282248 | 2025-10-02 00:24:25.282319 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-02 00:24:25.323323 | 2025-10-02 00:24:25.323831 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-02 00:24:25.353262 | controller | skipping: Conditional result was False 2025-10-02 00:24:25.366976 | 2025-10-02 00:24:25.367123 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-02 00:24:25.394609 | controller | skipping: Conditional result was False 2025-10-02 00:24:25.408124 | 2025-10-02 00:24:25.408269 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-02 00:24:25.434810 | controller | skipping: Conditional result was False 2025-10-02 00:24:25.482752 | 2025-10-02 00:24:25.482841 | PLAY RECAP 2025-10-02 00:24:25.482900 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-02 00:24:25.482927 | 2025-10-02 00:24:25.634805 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-02 00:24:25.635654 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-02 00:24:26.234753 | 2025-10-02 00:24:26.234870 | PLAY [all:!appliance*] 2025-10-02 00:24:26.256471 | 2025-10-02 00:24:26.256548 | TASK [unregister the node] 2025-10-02 00:24:26.612580 | controller | skipping: Conditional result was False 2025-10-02 00:24:26.619226 | 2025-10-02 00:24:26.619309 | TASK [include_role : fetch-output] 2025-10-02 00:24:26.669371 | controller | ok 2025-10-02 00:24:26.704454 | 2025-10-02 00:24:26.704588 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-02 00:24:26.780829 | controller | skipping: Conditional result was False 2025-10-02 00:24:26.787718 | 2025-10-02 00:24:26.787794 | TASK [fetch-output : Set log path for single node] 2025-10-02 00:24:26.829715 | controller | ok 2025-10-02 00:24:26.835957 | 2025-10-02 00:24:26.836031 | LOOP [fetch-output : Ensure local output dirs] 2025-10-02 00:24:27.275654 | controller -> localhost | ok: "/var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/work/logs" 2025-10-02 00:24:27.499812 | controller -> localhost | changed: "/var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/work/artifacts" 2025-10-02 00:24:27.728055 | controller -> localhost | changed: "/var/lib/zuul/builds/d2e20e30441a4043be190fe3edaf537b/work/docs" 2025-10-02 00:24:27.745239 | 2025-10-02 00:24:27.745376 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-02 00:24:29.993103 | controller | changed: 2025-10-02 00:24:29.993516 | controller | .d..t...... ./ 2025-10-02 00:24:29.993563 | controller | cd+++++++++ controller/ 2025-10-02 00:24:29.993621 | controller | changed: All items complete 2025-10-02 00:24:29.993651 | 2025-10-02 00:24:32.097736 | controller | changed: .d..t...... ./ 2025-10-02 00:24:34.213690 | controller | changed: .d..t...... ./ 2025-10-02 00:24:34.243506 | 2025-10-02 00:24:34.243741 | TASK [include_role : fetch-output-openshift] 2025-10-02 00:24:34.280623 | controller | skipping: Conditional result was False 2025-10-02 00:24:34.290913 | 2025-10-02 00:24:34.291009 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-02 00:24:34.343580 | controller | skipping: Conditional result was False 2025-10-02 00:24:34.353839 | controller | skipping: Conditional result was False 2025-10-02 00:24:34.412288 | 2025-10-02 00:24:34.412489 | PLAY [localhost] 2025-10-02 00:24:34.430605 | 2025-10-02 00:24:34.430712 | TASK [Run Zuul manifest role] 2025-10-02 00:24:34.468928 | localhost | ok 2025-10-02 00:24:34.496411 | 2025-10-02 00:24:34.496609 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-02 00:24:34.980366 | localhost | changed 2025-10-02 00:24:34.986269 | 2025-10-02 00:24:34.986384 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-02 00:24:35.037207 | localhost | ok 2025-10-02 00:24:35.046336 | 2025-10-02 00:24:35.046401 | TASK [Set zuul-log-path fact] 2025-10-02 00:24:35.117264 | localhost | ok 2025-10-02 00:24:35.135494 | 2025-10-02 00:24:35.135580 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-02 00:24:35.203646 | localhost | ok 2025-10-02 00:24:35.211804 | 2025-10-02 00:24:35.211865 | LOOP [Run upload-logs-swift role] 2025-10-02 00:24:35.240771 | localhost | Output suppressed because no_log was given 2025-10-02 00:24:35.267719 | 2025-10-02 00:24:35.267827 | TASK [Set zuul-log-path fact] 2025-10-02 00:24:35.304020 | localhost | skipping: Conditional result was False 2025-10-02 00:24:35.309488 | 2025-10-02 00:24:35.309554 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-02 00:24:35.690230 | localhost -> localhost | ok: Runtime: 0:00:00.011985 2025-10-02 00:24:35.696440 | 2025-10-02 00:24:35.696513 | TASK [upload-logs-swift : Upload logs to swift]