2025-10-22 00:06:33.027775 | Job console starting... 2025-10-22 00:06:33.038278 | Updating repositories 2025-10-22 00:06:35.646038 | Preparing job workspace 2025-10-22 00:06:39.160086 | Running Ansible setup... 2025-10-22 00:06:45.873230 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-22 00:06:46.583569 | 2025-10-22 00:06:46.583773 | PLAY [localhost] 2025-10-22 00:06:46.595066 | 2025-10-22 00:06:46.595320 | TASK [Gathering Facts] 2025-10-22 00:06:47.729676 | localhost | ok 2025-10-22 00:06:47.757332 | 2025-10-22 00:06:47.757472 | TASK [Setup log path fact] 2025-10-22 00:06:47.781336 | localhost | ok 2025-10-22 00:06:47.803531 | 2025-10-22 00:06:47.803747 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-22 00:06:47.836490 | localhost | ok 2025-10-22 00:06:47.845768 | 2025-10-22 00:06:47.846007 | TASK [emit-job-header : Print job information] 2025-10-22 00:06:47.887533 | # Job Information 2025-10-22 00:06:47.887751 | Ansible Version: 2.15.12 2025-10-22 00:06:47.887788 | Job: ansible-test-sanity-docker-devel 2025-10-22 00:06:47.887815 | Pipeline: periodic 2025-10-22 00:06:47.887841 | Executor: ze01.softwarefactory-project.io 2025-10-22 00:06:47.887867 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-22 00:06:47.887895 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/219/ansible/2199bb884a5e4d989c32a5bcc992baed/ 2025-10-22 00:06:47.887921 | Event ID: 29cce05ecf284232acebc18c8d35e894 2025-10-22 00:06:47.892231 | 2025-10-22 00:06:47.892317 | LOOP [emit-job-header : Print node information] 2025-10-22 00:06:48.002315 | localhost | ok: 2025-10-22 00:06:48.002532 | localhost | # Node Information 2025-10-22 00:06:48.002560 | localhost | Inventory Hostname: controller 2025-10-22 00:06:48.002583 | localhost | Hostname: ip-172-16-165-98 2025-10-22 00:06:48.002611 | localhost | Username: zuul-worker 2025-10-22 00:06:48.002634 | localhost | Distro: Fedora 37 2025-10-22 00:06:48.002653 | localhost | Provider: ansible-us-east-2 2025-10-22 00:06:48.002671 | localhost | Region: us-east-2 2025-10-22 00:06:48.002687 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-22 00:06:48.002704 | localhost | Product Name: t3.small 2025-10-22 00:06:48.002721 | localhost | Interface IP: 3.23.86.237 2025-10-22 00:06:48.021734 | 2025-10-22 00:06:48.021950 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-22 00:06:48.405524 | localhost -> localhost | changed 2025-10-22 00:06:48.414667 | 2025-10-22 00:06:48.414879 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-22 00:06:49.281621 | localhost -> localhost | changed 2025-10-22 00:06:49.304762 | 2025-10-22 00:06:49.304875 | PLAY [all:!appliance*] 2025-10-22 00:06:49.332357 | 2025-10-22 00:06:49.332556 | TASK [include_role : start-zuul-console] 2025-10-22 00:06:49.353851 | controller | ok 2025-10-22 00:06:49.368131 | 2025-10-22 00:06:49.368199 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-22 00:06:50.050595 | controller | ok 2025-10-22 00:06:50.079907 | 2025-10-22 00:06:50.080094 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-22 00:06:55.259798 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-22 00:06:55.266477 | 2025-10-22 00:06:55.266587 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-22 00:06:55.412493 | controller | skipping: Conditional result was False 2025-10-22 00:06:55.421302 | 2025-10-22 00:06:55.421404 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-22 00:06:55.456812 | controller | skipping: Conditional result was False 2025-10-22 00:06:55.471535 | 2025-10-22 00:06:55.471713 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-22 00:06:55.531094 | controller | skipping: Conditional result was False 2025-10-22 00:06:55.540763 | 2025-10-22 00:06:55.540895 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-22 00:06:55.576647 | controller | skipping: Conditional result was False 2025-10-22 00:06:55.587310 | 2025-10-22 00:06:55.587493 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-22 00:06:55.625780 | controller | skipping: Conditional result was False 2025-10-22 00:06:55.642812 | 2025-10-22 00:06:55.643394 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-22 00:06:55.682393 | controller | skipping: Conditional result was False 2025-10-22 00:06:55.707364 | 2025-10-22 00:06:55.707470 | TASK [Disable Fedora Modular] 2025-10-22 00:06:56.438400 | controller | changed 2025-10-22 00:06:56.445742 | 2025-10-22 00:06:56.445821 | TASK [Enable EPEL] 2025-10-22 00:06:56.480867 | controller | skipping: Conditional result was False 2025-10-22 00:06:56.488681 | 2025-10-22 00:06:56.488794 | TASK [Register the RHEL node] 2025-10-22 00:06:56.675668 | 2025-10-22 00:06:56.675875 | TASK [Show the subscription-manager status] 2025-10-22 00:06:56.839238 | controller | skipping: Conditional result was False 2025-10-22 00:06:56.848798 | 2025-10-22 00:06:56.848902 | TASK [Enable EPEL on RHEL] 2025-10-22 00:06:57.020459 | controller | skipping: Conditional result was False 2025-10-22 00:06:57.036059 | 2025-10-22 00:06:57.036248 | TASK [Install git and tox] 2025-10-22 00:08:27.855303 | controller | changed 2025-10-22 00:08:27.874782 | 2025-10-22 00:08:27.874921 | TASK [include_role : prepare-workspace] 2025-10-22 00:08:27.901859 | controller | ok 2025-10-22 00:08:27.939340 | 2025-10-22 00:08:27.939585 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-22 00:08:28.538715 | controller | ok 2025-10-22 00:08:28.557370 | 2025-10-22 00:08:28.557639 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-22 00:08:42.725903 | controller | Output suppressed because no_log was given 2025-10-22 00:08:42.743694 | 2025-10-22 00:08:42.743991 | TASK [include_role : prepare-workspace-openshift] 2025-10-22 00:08:42.769712 | controller | skipping: Conditional result was False 2025-10-22 00:08:42.802634 | 2025-10-22 00:08:42.802742 | PLAY [all:!appliance] 2025-10-22 00:08:42.819921 | 2025-10-22 00:08:42.820002 | TASK [Run add-build-sshkey role (RSA)] 2025-10-22 00:08:42.844251 | controller | ok 2025-10-22 00:08:42.901253 | 2025-10-22 00:08:42.901385 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-22 00:08:43.201207 | controller -> localhost | ok 2025-10-22 00:08:43.215114 | 2025-10-22 00:08:43.215263 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-22 00:08:43.247969 | controller | ok 2025-10-22 00:08:43.264332 | controller | included: /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-22 00:08:43.272657 | 2025-10-22 00:08:43.272781 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-22 00:08:43.758485 | controller -> localhost | Generating public/private rsa key pair. 2025-10-22 00:08:43.758947 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/work/2199bb884a5e4d989c32a5bcc992baed_id_rsa. 2025-10-22 00:08:43.759100 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/work/2199bb884a5e4d989c32a5bcc992baed_id_rsa.pub. 2025-10-22 00:08:43.759177 | controller -> localhost | The key fingerprint is: 2025-10-22 00:08:43.759241 | controller -> localhost | SHA256:Kx3LyJm5SFkx9NYYBX3WqPf8fsVkLHv6zEBT4DgTS8g zuul-build-sshkey 2025-10-22 00:08:43.759298 | controller -> localhost | The key's randomart image is: 2025-10-22 00:08:43.759351 | controller -> localhost | +---[RSA 2048]----+ 2025-10-22 00:08:43.759404 | controller -> localhost | | . o=..oo. | 2025-10-22 00:08:43.759459 | controller -> localhost | | . . +E.+=.. | 2025-10-22 00:08:43.759512 | controller -> localhost | | o + .+= ...| 2025-10-22 00:08:43.759565 | controller -> localhost | | + . .o..+| 2025-10-22 00:08:43.759616 | controller -> localhost | | . S . oo* | 2025-10-22 00:08:43.759688 | controller -> localhost | | + B + .+.+| 2025-10-22 00:08:43.759750 | controller -> localhost | | o B = .+.| 2025-10-22 00:08:43.759808 | controller -> localhost | | . . o .+o| 2025-10-22 00:08:43.759870 | controller -> localhost | | . . o*| 2025-10-22 00:08:43.759937 | controller -> localhost | +----[SHA256]-----+ 2025-10-22 00:08:43.760120 | controller -> localhost | ok: Runtime: 0:00:00.093463 2025-10-22 00:08:43.777131 | 2025-10-22 00:08:43.777297 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-22 00:08:43.812896 | controller | ok 2025-10-22 00:08:43.833204 | controller | included: /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-22 00:08:43.855093 | 2025-10-22 00:08:43.855217 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-22 00:08:43.878899 | controller | skipping: Conditional result was False 2025-10-22 00:08:43.885407 | 2025-10-22 00:08:43.885486 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-22 00:08:44.499924 | controller | changed 2025-10-22 00:08:44.508433 | 2025-10-22 00:08:44.508533 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-22 00:08:44.865724 | controller | ok 2025-10-22 00:08:44.880776 | 2025-10-22 00:08:44.880942 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-22 00:08:46.632506 | controller | changed 2025-10-22 00:08:46.640736 | 2025-10-22 00:08:46.640826 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-22 00:08:48.292774 | controller | changed 2025-10-22 00:08:48.305771 | 2025-10-22 00:08:48.305927 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-22 00:08:48.343669 | controller | skipping: Conditional result was False 2025-10-22 00:08:48.360401 | 2025-10-22 00:08:48.360645 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-22 00:08:48.766365 | controller -> localhost | changed 2025-10-22 00:08:48.783208 | 2025-10-22 00:08:48.783334 | TASK [add-build-sshkey : Add back temp key] 2025-10-22 00:08:49.105649 | controller -> localhost | Identity added: /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/work/2199bb884a5e4d989c32a5bcc992baed_id_rsa (zuul-build-sshkey) 2025-10-22 00:08:49.106133 | controller -> localhost | ok: Runtime: 0:00:00.014266 2025-10-22 00:08:49.124259 | 2025-10-22 00:08:49.124433 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-22 00:08:49.669192 | controller | ok 2025-10-22 00:08:49.681767 | 2025-10-22 00:08:49.681939 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-22 00:08:49.709780 | controller | skipping: Conditional result was False 2025-10-22 00:08:49.740366 | 2025-10-22 00:08:49.740579 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-22 00:08:49.779939 | controller | ok 2025-10-22 00:08:49.809590 | 2025-10-22 00:08:49.809745 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-22 00:08:50.145229 | controller -> localhost | ok 2025-10-22 00:08:50.153965 | 2025-10-22 00:08:50.154112 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-22 00:08:50.186459 | controller | ok 2025-10-22 00:08:50.206103 | controller | included: /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-22 00:08:50.213222 | 2025-10-22 00:08:50.213347 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-22 00:08:50.524307 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-22 00:08:50.524479 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/work/2199bb884a5e4d989c32a5bcc992baed_id_ecdsa. 2025-10-22 00:08:50.524509 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/work/2199bb884a5e4d989c32a5bcc992baed_id_ecdsa.pub. 2025-10-22 00:08:50.524540 | controller -> localhost | The key fingerprint is: 2025-10-22 00:08:50.524562 | controller -> localhost | SHA256:DmiskotGedtTHkqVX/DaSK+/8pLZvBcHdAK4s2XJspc zuul-build-sshkey 2025-10-22 00:08:50.524584 | controller -> localhost | The key's randomart image is: 2025-10-22 00:08:50.524604 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-22 00:08:50.524624 | controller -> localhost | | ... | 2025-10-22 00:08:50.524643 | controller -> localhost | | o o . | 2025-10-22 00:08:50.524663 | controller -> localhost | | . = o o | 2025-10-22 00:08:50.524681 | controller -> localhost | | . . o = B . | 2025-10-22 00:08:50.524701 | controller -> localhost | | . + o S & . . | 2025-10-22 00:08:50.524720 | controller -> localhost | | + + . = * E . . | 2025-10-22 00:08:50.524739 | controller -> localhost | |+ o + + o B o | 2025-10-22 00:08:50.524758 | controller -> localhost | |.+ . + . * o . | 2025-10-22 00:08:50.524778 | controller -> localhost | |+ . ==+ | 2025-10-22 00:08:50.524797 | controller -> localhost | +----[SHA256]-----+ 2025-10-22 00:08:50.524854 | controller -> localhost | ok: Runtime: 0:00:00.012902 2025-10-22 00:08:50.533122 | 2025-10-22 00:08:50.533193 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-22 00:08:50.553041 | controller | ok 2025-10-22 00:08:50.560921 | controller | included: /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-22 00:08:50.571582 | 2025-10-22 00:08:50.571702 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-22 00:08:50.586260 | controller | skipping: Conditional result was False 2025-10-22 00:08:50.593219 | 2025-10-22 00:08:50.593293 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-22 00:08:51.086121 | controller | changed 2025-10-22 00:08:51.098494 | 2025-10-22 00:08:51.098761 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-22 00:08:51.460264 | controller | ok 2025-10-22 00:08:51.474108 | 2025-10-22 00:08:51.474261 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-22 00:08:53.628401 | controller | changed 2025-10-22 00:08:53.643133 | 2025-10-22 00:08:53.643338 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-22 00:08:55.036860 | controller | changed 2025-10-22 00:08:55.044920 | 2025-10-22 00:08:55.045074 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-22 00:08:55.060259 | controller | skipping: Conditional result was False 2025-10-22 00:08:55.070169 | 2025-10-22 00:08:55.070272 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-22 00:08:55.330232 | controller -> localhost | changed 2025-10-22 00:08:55.356482 | 2025-10-22 00:08:55.356665 | TASK [add-build-sshkey : Add back temp key] 2025-10-22 00:08:55.639216 | controller -> localhost | Identity added: /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/work/2199bb884a5e4d989c32a5bcc992baed_id_ecdsa (zuul-build-sshkey) 2025-10-22 00:08:55.639456 | controller -> localhost | ok: Runtime: 0:00:00.008438 2025-10-22 00:08:55.646082 | 2025-10-22 00:08:55.646145 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-22 00:08:55.982958 | controller | ok 2025-10-22 00:08:55.991258 | 2025-10-22 00:08:55.991356 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-22 00:08:56.026616 | controller | skipping: Conditional result was False 2025-10-22 00:08:56.067506 | 2025-10-22 00:08:56.067654 | TASK [include_role : remove-zuul-sshkey] 2025-10-22 00:08:56.081715 | controller | skipping: Conditional result was False 2025-10-22 00:08:56.088816 | 2025-10-22 00:08:56.088889 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-22 00:08:56.465682 | controller | ok: "logs" 2025-10-22 00:08:56.466048 | controller | ok: All items complete 2025-10-22 00:08:56.466102 | 2025-10-22 00:08:56.779862 | controller | ok: "artifacts" 2025-10-22 00:08:57.104848 | controller | ok: "docs" 2025-10-22 00:08:57.131426 | 2025-10-22 00:08:57.131786 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-22 00:08:57.520553 | controller | changed: "logs" 2025-10-22 00:08:57.831722 | controller | changed: "artifacts" 2025-10-22 00:08:58.182819 | controller | changed: "docs" 2025-10-22 00:08:58.238742 | 2025-10-22 00:08:58.238863 | PLAY RECAP 2025-10-22 00:08:58.238921 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-22 00:08:58.238958 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-22 00:08:58.238984 | 2025-10-22 00:08:58.401548 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-22 00:08:58.402668 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-22 00:08:59.105270 | 2025-10-22 00:08:59.105428 | PLAY [all] 2025-10-22 00:08:59.134606 | 2025-10-22 00:08:59.134748 | TASK [Install binary dependencies] 2025-10-22 00:08:59.218412 | controller | ok 2025-10-22 00:08:59.245459 | 2025-10-22 00:08:59.245614 | TASK [bindep : Include find tasks] 2025-10-22 00:08:59.277802 | controller | ok 2025-10-22 00:08:59.288490 | controller | included: /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-22 00:08:59.295996 | 2025-10-22 00:08:59.296146 | TASK [bindep : Look for bindep.txt] 2025-10-22 00:08:59.872710 | controller | ok 2025-10-22 00:08:59.887496 | 2025-10-22 00:08:59.887699 | TASK [bindep : Define bindep_file fact] 2025-10-22 00:08:59.915627 | controller | skipping: Conditional result was False 2025-10-22 00:08:59.930235 | 2025-10-22 00:08:59.930446 | TASK [bindep : Look for other-requirements.txt] 2025-10-22 00:09:00.394063 | controller | ok 2025-10-22 00:09:00.404800 | 2025-10-22 00:09:00.404998 | TASK [bindep : Define bindep_file fact] 2025-10-22 00:09:00.444825 | controller | skipping: Conditional result was False 2025-10-22 00:09:00.458774 | 2025-10-22 00:09:00.458929 | TASK [bindep : Look for bindep fallback file] 2025-10-22 00:09:00.486076 | controller | skipping: Conditional result was False 2025-10-22 00:09:00.499965 | 2025-10-22 00:09:00.500150 | TASK [bindep : Define bindep_file fact] 2025-10-22 00:09:00.527398 | controller | skipping: Conditional result was False 2025-10-22 00:09:00.543877 | 2025-10-22 00:09:00.544067 | TASK [bindep : Include bindep tasks] 2025-10-22 00:09:00.571344 | controller | skipping: Conditional result was False 2025-10-22 00:09:00.584912 | 2025-10-22 00:09:00.585092 | TASK [bindep : Include install tasks] 2025-10-22 00:09:00.612065 | controller | skipping: Conditional result was False 2025-10-22 00:09:00.626063 | 2025-10-22 00:09:00.626226 | LOOP [bindep : Include package tasks] 2025-10-22 00:09:00.698381 | 2025-10-22 00:09:00.698658 | TASK [Run test-setup role] 2025-10-22 00:09:00.723535 | controller | ok 2025-10-22 00:09:00.755592 | 2025-10-22 00:09:00.755753 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-22 00:09:01.097597 | controller | ok 2025-10-22 00:09:01.110218 | 2025-10-22 00:09:01.110355 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-22 00:09:01.260930 | controller | skipping: Conditional result was False 2025-10-22 00:09:01.309833 | 2025-10-22 00:09:01.309955 | PLAY RECAP 2025-10-22 00:09:01.310010 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-22 00:09:01.310067 | 2025-10-22 00:09:01.411155 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-22 00:09:01.414705 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-22 00:09:02.036720 | 2025-10-22 00:09:02.036864 | PLAY [controller] 2025-10-22 00:09:02.057888 | 2025-10-22 00:09:02.058012 | TASK [Create the /root directory] 2025-10-22 00:09:03.019617 | controller | ok 2025-10-22 00:09:03.025560 | 2025-10-22 00:09:03.025641 | TASK [Install glibc-langpack-en] 2025-10-22 00:09:13.618439 | controller | ok: Nothing to do 2025-10-22 00:09:13.630118 | 2025-10-22 00:09:13.630253 | TASK [Ensure controller directory exists] 2025-10-22 00:09:14.161425 | controller | changed 2025-10-22 00:09:14.174006 | 2025-10-22 00:09:14.174192 | TASK [Install container runtime] 2025-10-22 00:09:14.241136 | controller | ok 2025-10-22 00:09:14.295599 | 2025-10-22 00:09:14.295713 | LOOP [ensure-podman : Find distribution installation] 2025-10-22 00:09:14.331884 | controller | ok: "/var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-22 00:09:14.358781 | controller | included: /var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-22 00:09:14.370853 | 2025-10-22 00:09:14.370949 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-22 00:10:39.314010 | controller | changed 2025-10-22 00:10:39.323983 | 2025-10-22 00:10:39.324148 | TASK [ensure-podman : Fetch podman version] 2025-10-22 00:10:40.066199 | controller | Client: Podman Engine 2025-10-22 00:10:40.066301 | controller | Version: 4.6.2 2025-10-22 00:10:40.066343 | controller | API Version: 4.6.2 2025-10-22 00:10:40.066383 | controller | Go Version: go1.19.12 2025-10-22 00:10:40.066437 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-22 00:10:40.066481 | controller | OS/Arch: linux/amd64 2025-10-22 00:10:40.478296 | controller | ok: Runtime: 0:00:00.238790 2025-10-22 00:10:40.491790 | 2025-10-22 00:10:40.491904 | TASK [ensure-podman : Print podman version installed] 2025-10-22 00:10:40.525971 | Podman version: Client: Podman Engine 2025-10-22 00:10:40.526141 | Version: 4.6.2 2025-10-22 00:10:40.526173 | API Version: 4.6.2 2025-10-22 00:10:40.526202 | Go Version: go1.19.12 2025-10-22 00:10:40.526232 | Built: Mon Aug 28 19:38:31 2023 2025-10-22 00:10:40.526262 | OS/Arch: linux/amd64 2025-10-22 00:10:40.533045 | 2025-10-22 00:10:40.533127 | TASK [ensure-podman : Validate podman engine] 2025-10-22 00:10:40.683504 | controller | skipping: Conditional result was False 2025-10-22 00:10:40.690790 | 2025-10-22 00:10:40.690917 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-22 00:10:40.707366 | controller | skipping: Conditional result was False 2025-10-22 00:10:40.733582 | 2025-10-22 00:10:40.733691 | TASK [Ensure python3.8 is present] 2025-10-22 00:10:40.772472 | controller | skipping: Conditional result was False 2025-10-22 00:10:40.778681 | 2025-10-22 00:10:40.778777 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-22 00:10:40.810064 | controller | ok 2025-10-22 00:10:40.848734 | 2025-10-22 00:10:40.848854 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-22 00:10:44.553089 | controller | ok: Nothing to do 2025-10-22 00:10:44.589396 | 2025-10-22 00:10:44.589619 | TASK [our-ensure-python : Also install python3-devel] 2025-10-22 00:10:59.388758 | controller | changed 2025-10-22 00:10:59.401757 | 2025-10-22 00:10:59.401882 | TASK [Run ensure-virtualenv role] 2025-10-22 00:10:59.424197 | controller | ok 2025-10-22 00:10:59.448397 | 2025-10-22 00:10:59.448514 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-22 00:10:59.937385 | controller | /usr/bin/virtualenv 2025-10-22 00:11:00.123785 | controller | ok: Runtime: 0:00:00.004719 2025-10-22 00:11:00.131473 | 2025-10-22 00:11:00.131560 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-22 00:11:00.156550 | controller | skipping: Conditional result was False 2025-10-22 00:11:00.156853 | controller | ok: All items complete 2025-10-22 00:11:00.156880 | 2025-10-22 00:11:00.190939 | 2025-10-22 00:11:00.191448 | TASK [Find the full path of the Python interpreter] 2025-10-22 00:11:00.647456 | controller | /usr/bin/python3 2025-10-22 00:11:00.858826 | controller | ok 2025-10-22 00:11:00.873271 | 2025-10-22 00:11:00.873399 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-22 00:11:02.583243 | controller | created virtual environment CPython3.11.0.final.0-64 in 909ms 2025-10-22 00:11:02.708023 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-22 00:11:02.708083 | 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-10-22 00:11:02.708101 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-22 00:11:02.708125 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-22 00:11:03.100292 | controller | changed 2025-10-22 00:11:03.107411 | 2025-10-22 00:11:03.107621 | TASK [Set selinux package] 2025-10-22 00:11:03.134209 | controller | ok 2025-10-22 00:11:03.141805 | 2025-10-22 00:11:03.142043 | TASK [Set selinux package (Fedora)] 2025-10-22 00:11:03.177908 | controller | ok 2025-10-22 00:11:03.186898 | 2025-10-22 00:11:03.187078 | TASK [Install selinux into virtualenv] 2025-10-22 00:11:05.769338 | controller | Collecting selinux-please-lie-to-me 2025-10-22 00:11:05.884446 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-22 00:11:06.416652 | controller | Collecting setuptools<50.0.0 2025-10-22 00:11:06.438317 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-22 00:11:06.560977 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00 2025-10-22 00:11:06.718721 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-22 00:11:06.719149 | controller | Attempting uninstall: setuptools 2025-10-22 00:11:06.724168 | controller | Found existing installation: setuptools 62.6.0 2025-10-22 00:11:06.835620 | controller | Uninstalling setuptools-62.6.0: 2025-10-22 00:11:06.851076 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-22 00:11:07.623579 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-22 00:11:07.831525 | controller | 2025-10-22 00:11:08.047841 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-22 00:11:08.047892 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-22 00:11:08.352301 | controller | ok: Runtime: 0:00:04.389775 2025-10-22 00:11:08.362785 | 2025-10-22 00:11:08.362936 | TASK [Install pytest-forked into virtualenv] 2025-10-22 00:11:09.579378 | controller | Collecting pytest-forked 2025-10-22 00:11:09.666514 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-22 00:11:09.752746 | controller | Collecting py 2025-10-22 00:11:09.765349 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-22 00:11:09.802019 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.2 MB/s eta 0:00:00 2025-10-22 00:11:09.978803 | controller | Collecting pytest>=3.10 2025-10-22 00:11:09.997206 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-22 00:11:10.058153 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.3 MB/s eta 0:00:00 2025-10-22 00:11:10.114933 | controller | Collecting iniconfig>=1 2025-10-22 00:11:10.127451 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-22 00:11:10.192997 | controller | Collecting packaging>=20 2025-10-22 00:11:10.205064 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-22 00:11:10.217167 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.8 MB/s eta 0:00:00 2025-10-22 00:11:10.264083 | controller | Collecting pluggy<2,>=1.5 2025-10-22 00:11:10.277737 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-22 00:11:10.348547 | controller | Collecting pygments>=2.7.2 2025-10-22 00:11:10.360448 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-22 00:11:10.480281 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.5 MB/s eta 0:00:00 2025-10-22 00:11:10.614585 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-22 00:11:12.862268 | controller | Successfully installed iniconfig-2.3.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-22 00:11:12.878356 | controller | 2025-10-22 00:11:13.065647 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-22 00:11:13.065711 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-22 00:11:13.540524 | controller | ok: Runtime: 0:00:04.224781 2025-10-22 00:11:13.548586 | 2025-10-22 00:11:13.548681 | TASK [Update pip] 2025-10-22 00:11:14.678992 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-22 00:11:14.930587 | controller | Collecting pip 2025-10-22 00:11:15.028729 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-22 00:11:15.228114 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.1 MB/s eta 0:00:00 2025-10-22 00:11:15.352177 | controller | Installing collected packages: pip 2025-10-22 00:11:15.352587 | controller | Attempting uninstall: pip 2025-10-22 00:11:15.357170 | controller | Found existing installation: pip 22.2.2 2025-10-22 00:11:15.614178 | controller | Uninstalling pip-22.2.2: 2025-10-22 00:11:15.643418 | controller | Successfully uninstalled pip-22.2.2 2025-10-22 00:11:17.379799 | controller | Successfully installed pip-25.2 2025-10-22 00:11:17.702558 | controller | ok: Runtime: 0:00:03.508525 2025-10-22 00:11:17.711271 | 2025-10-22 00:11:17.711389 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-22 00:11:18.223503 | controller | changed 2025-10-22 00:11:18.229648 | 2025-10-22 00:11:18.229729 | TASK [Install ansible into virtualenv] 2025-10-22 00:11:19.264802 | controller | Processing ./src/github.com/ansible/ansible 2025-10-22 00:11:19.271157 | controller | Installing build dependencies: started 2025-10-22 00:11:20.999741 | controller | Installing build dependencies: finished with status 'done' 2025-10-22 00:11:22.527756 | controller | Getting requirements to build wheel: started 2025-10-22 00:11:22.527824 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-22 00:11:22.529389 | controller | Preparing metadata (pyproject.toml): started 2025-10-22 00:11:23.453756 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-22 00:11:23.458396 | 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-22 00:11:23.463448 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-22 00:11:23.881416 | controller | ERROR 2025-10-22 00:11:23.881621 | controller | { 2025-10-22 00:11:23.881654 | controller | "delta": "0:00:04.976245", 2025-10-22 00:11:23.881674 | controller | "end": "2025-10-22 00:11:23.613721", 2025-10-22 00:11:23.881692 | controller | "msg": "non-zero return code", 2025-10-22 00:11:23.881719 | controller | "rc": 1, 2025-10-22 00:11:23.881736 | controller | "start": "2025-10-22 00:11:18.637476" 2025-10-22 00:11:23.881752 | controller | } failure 2025-10-22 00:11:23.883348 | 2025-10-22 00:11:23.883394 | PLAY RECAP 2025-10-22 00:11:23.883437 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-22 00:11:23.883457 | 2025-10-22 00:11:24.022156 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-22 00:11:24.023530 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-22 00:11:24.829291 | 2025-10-22 00:11:24.829539 | PLAY [all] 2025-10-22 00:11:24.854741 | 2025-10-22 00:11:24.854942 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-22 00:11:25.643888 | controller | changed: non-zero return code 2025-10-22 00:11:25.651579 | 2025-10-22 00:11:25.651764 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-22 00:11:25.676860 | controller | skipping: Conditional result was False 2025-10-22 00:11:25.683380 | 2025-10-22 00:11:25.683484 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-22 00:11:25.714958 | 2025-10-22 00:11:25.715154 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-22 00:11:25.739362 | 2025-10-22 00:11:25.739555 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-22 00:11:25.754501 | controller | skipping: Conditional result was False 2025-10-22 00:11:25.760764 | 2025-10-22 00:11:25.760880 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-22 00:11:25.792276 | 2025-10-22 00:11:25.792461 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-22 00:11:25.806649 | controller | skipping: Conditional result was False 2025-10-22 00:11:25.813894 | 2025-10-22 00:11:25.814069 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-22 00:11:25.828635 | controller | skipping: Conditional result was False 2025-10-22 00:11:25.837642 | 2025-10-22 00:11:25.837779 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-22 00:11:25.864126 | controller | skipping: Conditional result was False 2025-10-22 00:11:25.901390 | 2025-10-22 00:11:25.901490 | PLAY RECAP 2025-10-22 00:11:25.901533 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-22 00:11:25.901555 | 2025-10-22 00:11:26.037904 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-22 00:11:26.039330 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-22 00:11:26.716488 | 2025-10-22 00:11:26.716689 | PLAY [all:!appliance*] 2025-10-22 00:11:26.751407 | 2025-10-22 00:11:26.751540 | TASK [unregister the node] 2025-10-22 00:11:26.901655 | controller | skipping: Conditional result was False 2025-10-22 00:11:26.910342 | 2025-10-22 00:11:26.910576 | TASK [include_role : fetch-output] 2025-10-22 00:11:26.942457 | controller | ok 2025-10-22 00:11:26.966414 | 2025-10-22 00:11:26.966580 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-22 00:11:27.024068 | controller | skipping: Conditional result was False 2025-10-22 00:11:27.029766 | 2025-10-22 00:11:27.029841 | TASK [fetch-output : Set log path for single node] 2025-10-22 00:11:27.061048 | controller | ok 2025-10-22 00:11:27.067717 | 2025-10-22 00:11:27.067846 | LOOP [fetch-output : Ensure local output dirs] 2025-10-22 00:11:27.506165 | controller -> localhost | ok: "/var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/work/logs" 2025-10-22 00:11:27.770347 | controller -> localhost | changed: "/var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/work/artifacts" 2025-10-22 00:11:28.045925 | controller -> localhost | changed: "/var/lib/zuul/builds/2199bb884a5e4d989c32a5bcc992baed/work/docs" 2025-10-22 00:11:28.056711 | 2025-10-22 00:11:28.056835 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-22 00:11:29.406409 | controller | changed: 2025-10-22 00:11:29.406657 | controller | .d..t...... ./ 2025-10-22 00:11:29.406708 | controller | cd+++++++++ controller/ 2025-10-22 00:11:29.406765 | controller | changed: All items complete 2025-10-22 00:11:29.406803 | 2025-10-22 00:11:30.523120 | controller | changed: .d..t...... ./ 2025-10-22 00:11:31.649059 | controller | changed: .d..t...... ./ 2025-10-22 00:11:31.672818 | 2025-10-22 00:11:31.672962 | TASK [include_role : fetch-output-openshift] 2025-10-22 00:11:31.688778 | controller | skipping: Conditional result was False 2025-10-22 00:11:31.698142 | 2025-10-22 00:11:31.698301 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-22 00:11:31.738484 | controller | skipping: Conditional result was False 2025-10-22 00:11:31.750493 | controller | skipping: Conditional result was False 2025-10-22 00:11:31.793600 | 2025-10-22 00:11:31.793717 | PLAY [localhost] 2025-10-22 00:11:31.810588 | 2025-10-22 00:11:31.810725 | TASK [Run Zuul manifest role] 2025-10-22 00:11:31.830654 | localhost | ok 2025-10-22 00:11:31.849335 | 2025-10-22 00:11:31.849473 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-22 00:11:32.221735 | localhost | changed 2025-10-22 00:11:32.229549 | 2025-10-22 00:11:32.229692 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-22 00:11:32.262346 | localhost | ok 2025-10-22 00:11:32.274832 | 2025-10-22 00:11:32.274979 | TASK [Set zuul-log-path fact] 2025-10-22 00:11:32.297136 | localhost | ok 2025-10-22 00:11:32.320832 | 2025-10-22 00:11:32.320987 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-22 00:11:32.352083 | localhost | ok 2025-10-22 00:11:32.365280 | 2025-10-22 00:11:32.365435 | LOOP [Run upload-logs-swift role] 2025-10-22 00:11:32.401476 | localhost | Output suppressed because no_log was given 2025-10-22 00:11:32.432248 | 2025-10-22 00:11:32.432404 | TASK [Set zuul-log-path fact] 2025-10-22 00:11:32.457217 | localhost | skipping: Conditional result was False 2025-10-22 00:11:32.464828 | 2025-10-22 00:11:32.464920 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-22 00:11:32.974177 | localhost -> localhost | ok: Runtime: 0:00:00.006162 2025-10-22 00:11:32.982177 | 2025-10-22 00:11:32.982350 | TASK [upload-logs-swift : Upload logs to swift]