2025-10-27 00:17:23.141943 | Job console starting... 2025-10-27 00:17:23.153749 | Updating repositories 2025-10-27 00:17:23.275293 | Preparing job workspace 2025-10-27 00:17:27.051511 | Running Ansible setup... 2025-10-27 00:17:33.611545 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-27 00:17:34.260372 | 2025-10-27 00:17:34.260524 | PLAY [localhost] 2025-10-27 00:17:34.269921 | 2025-10-27 00:17:34.270043 | TASK [Gathering Facts] 2025-10-27 00:17:35.357473 | localhost | ok 2025-10-27 00:17:35.380075 | 2025-10-27 00:17:35.380207 | TASK [Setup log path fact] 2025-10-27 00:17:35.401915 | localhost | ok 2025-10-27 00:17:35.421267 | 2025-10-27 00:17:35.421439 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-27 00:17:35.456799 | localhost | ok 2025-10-27 00:17:35.469131 | 2025-10-27 00:17:35.469286 | TASK [emit-job-header : Print job information] 2025-10-27 00:17:35.510659 | # Job Information 2025-10-27 00:17:35.510871 | Ansible Version: 2.15.12 2025-10-27 00:17:35.510910 | Job: ansible-test-sanity-docker-devel 2025-10-27 00:17:35.510931 | Pipeline: periodic 2025-10-27 00:17:35.510951 | Executor: ze04.softwarefactory-project.io 2025-10-27 00:17:35.510970 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-27 00:17:35.510992 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/c34/ansible/c34633e5beb943978c994c50c2047f47/ 2025-10-27 00:17:35.511013 | Event ID: 750469794ad743fdb26497abfe8a4902 2025-10-27 00:17:35.515460 | 2025-10-27 00:17:35.515529 | LOOP [emit-job-header : Print node information] 2025-10-27 00:17:35.643580 | localhost | ok: 2025-10-27 00:17:35.643944 | localhost | # Node Information 2025-10-27 00:17:35.643977 | localhost | Inventory Hostname: controller 2025-10-27 00:17:35.643998 | localhost | Hostname: ip-172-16-102-123 2025-10-27 00:17:35.644017 | localhost | Username: zuul-worker 2025-10-27 00:17:35.644038 | localhost | Distro: Fedora 37 2025-10-27 00:17:35.644056 | localhost | Provider: ansible-us-east-2 2025-10-27 00:17:35.644073 | localhost | Region: us-east-2 2025-10-27 00:17:35.644090 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-27 00:17:35.644106 | localhost | Product Name: t3.small 2025-10-27 00:17:35.644122 | localhost | Interface IP: 3.19.67.154 2025-10-27 00:17:35.666258 | 2025-10-27 00:17:35.666387 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-27 00:17:36.154620 | localhost -> localhost | changed 2025-10-27 00:17:36.161048 | 2025-10-27 00:17:36.161124 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-27 00:17:37.121587 | localhost -> localhost | changed 2025-10-27 00:17:37.152061 | 2025-10-27 00:17:37.152231 | PLAY [all:!appliance*] 2025-10-27 00:17:37.177779 | 2025-10-27 00:17:37.177922 | TASK [include_role : start-zuul-console] 2025-10-27 00:17:37.198833 | controller | ok 2025-10-27 00:17:37.213627 | 2025-10-27 00:17:37.213749 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-27 00:17:37.912134 | controller | ok 2025-10-27 00:17:37.932198 | 2025-10-27 00:17:37.932602 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-27 00:17:40.252333 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-27 00:17:40.268123 | 2025-10-27 00:17:40.268271 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-27 00:17:40.419636 | controller | skipping: Conditional result was False 2025-10-27 00:17:40.429100 | 2025-10-27 00:17:40.429243 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-27 00:17:40.456959 | controller | skipping: Conditional result was False 2025-10-27 00:17:40.465958 | 2025-10-27 00:17:40.466095 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-27 00:17:40.493005 | controller | skipping: Conditional result was False 2025-10-27 00:17:40.502855 | 2025-10-27 00:17:40.503016 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-27 00:17:40.530120 | controller | skipping: Conditional result was False 2025-10-27 00:17:40.540190 | 2025-10-27 00:17:40.540376 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-27 00:17:40.566551 | controller | skipping: Conditional result was False 2025-10-27 00:17:40.579221 | 2025-10-27 00:17:40.579589 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-27 00:17:40.606799 | controller | skipping: Conditional result was False 2025-10-27 00:17:40.618201 | 2025-10-27 00:17:40.618292 | TASK [Disable Fedora Modular] 2025-10-27 00:17:41.394175 | controller | changed 2025-10-27 00:17:41.409641 | 2025-10-27 00:17:41.409944 | TASK [Enable EPEL] 2025-10-27 00:17:41.448500 | controller | skipping: Conditional result was False 2025-10-27 00:17:41.462095 | 2025-10-27 00:17:41.462210 | TASK [Register the RHEL node] 2025-10-27 00:17:41.628653 | 2025-10-27 00:17:41.628955 | TASK [Show the subscription-manager status] 2025-10-27 00:17:41.828378 | controller | skipping: Conditional result was False 2025-10-27 00:17:41.844838 | 2025-10-27 00:17:41.845087 | TASK [Enable EPEL on RHEL] 2025-10-27 00:17:41.996113 | controller | skipping: Conditional result was False 2025-10-27 00:17:42.011279 | 2025-10-27 00:17:42.011479 | TASK [Install git and tox] 2025-10-27 00:19:43.229240 | controller | changed 2025-10-27 00:19:43.236567 | 2025-10-27 00:19:43.236751 | TASK [include_role : prepare-workspace] 2025-10-27 00:19:43.278113 | controller | ok 2025-10-27 00:19:43.311618 | 2025-10-27 00:19:43.311845 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-27 00:19:43.818505 | controller | ok 2025-10-27 00:19:43.829212 | 2025-10-27 00:19:43.829303 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-27 00:19:56.558673 | controller | Output suppressed because no_log was given 2025-10-27 00:19:56.573056 | 2025-10-27 00:19:56.573205 | TASK [include_role : prepare-workspace-openshift] 2025-10-27 00:19:56.599551 | controller | skipping: Conditional result was False 2025-10-27 00:19:56.662691 | 2025-10-27 00:19:56.662785 | PLAY [all:!appliance] 2025-10-27 00:19:56.679092 | 2025-10-27 00:19:56.679247 | TASK [Run add-build-sshkey role (RSA)] 2025-10-27 00:19:56.709185 | controller | ok 2025-10-27 00:19:56.724966 | 2025-10-27 00:19:56.725097 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-27 00:19:56.986025 | controller -> localhost | ok 2025-10-27 00:19:56.997246 | 2025-10-27 00:19:56.997418 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-27 00:19:57.020945 | controller | ok 2025-10-27 00:19:57.036254 | controller | included: /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-27 00:19:57.042444 | 2025-10-27 00:19:57.042513 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-27 00:19:57.536871 | controller -> localhost | Generating public/private rsa key pair. 2025-10-27 00:19:57.537256 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/work/c34633e5beb943978c994c50c2047f47_id_rsa. 2025-10-27 00:19:57.537299 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/work/c34633e5beb943978c994c50c2047f47_id_rsa.pub. 2025-10-27 00:19:57.537329 | controller -> localhost | The key fingerprint is: 2025-10-27 00:19:57.537357 | controller -> localhost | SHA256:xmHU1qCEzW3FXQrQVYtKHpj+7jXqJpoZkv952ktMLmc zuul-build-sshkey 2025-10-27 00:19:57.537383 | controller -> localhost | The key's randomart image is: 2025-10-27 00:19:57.537409 | controller -> localhost | +---[RSA 2048]----+ 2025-10-27 00:19:57.537434 | controller -> localhost | | +oooBoo.oo| 2025-10-27 00:19:57.537460 | controller -> localhost | | .oo.B +.o..| 2025-10-27 00:19:57.537485 | controller -> localhost | | += o ... | 2025-10-27 00:19:57.537510 | controller -> localhost | | o..o o | 2025-10-27 00:19:57.537534 | controller -> localhost | | S. + | 2025-10-27 00:19:57.537572 | controller -> localhost | | .. = | 2025-10-27 00:19:57.537605 | controller -> localhost | | o . . E o | 2025-10-27 00:19:57.537633 | controller -> localhost | | o +.Ooo . | 2025-10-27 00:19:57.537658 | controller -> localhost | | =o+BB. | 2025-10-27 00:19:57.537719 | controller -> localhost | +----[SHA256]-----+ 2025-10-27 00:19:57.537798 | controller -> localhost | ok: Runtime: 0:00:00.063996 2025-10-27 00:19:57.548424 | 2025-10-27 00:19:57.548548 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-27 00:19:57.581854 | controller | ok 2025-10-27 00:19:57.595821 | controller | included: /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-27 00:19:57.608339 | 2025-10-27 00:19:57.608427 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-27 00:19:57.634393 | controller | skipping: Conditional result was False 2025-10-27 00:19:57.644999 | 2025-10-27 00:19:57.645138 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-27 00:19:58.358670 | controller | changed 2025-10-27 00:19:58.373144 | 2025-10-27 00:19:58.373353 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-27 00:19:58.721830 | controller | ok 2025-10-27 00:19:58.735581 | 2025-10-27 00:19:58.735760 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-27 00:20:00.226275 | controller | changed 2025-10-27 00:20:00.234376 | 2025-10-27 00:20:00.234608 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-27 00:20:03.194594 | controller | changed 2025-10-27 00:20:03.209978 | 2025-10-27 00:20:03.210601 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-27 00:20:03.250155 | controller | skipping: Conditional result was False 2025-10-27 00:20:03.266910 | 2025-10-27 00:20:03.267142 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-27 00:20:03.768072 | controller -> localhost | changed 2025-10-27 00:20:03.785255 | 2025-10-27 00:20:03.785403 | TASK [add-build-sshkey : Add back temp key] 2025-10-27 00:20:04.166211 | controller -> localhost | Identity added: /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/work/c34633e5beb943978c994c50c2047f47_id_rsa (zuul-build-sshkey) 2025-10-27 00:20:04.166577 | controller -> localhost | ok: Runtime: 0:00:00.009015 2025-10-27 00:20:04.179976 | 2025-10-27 00:20:04.180141 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-27 00:20:04.909813 | controller | ok 2025-10-27 00:20:04.916204 | 2025-10-27 00:20:04.916296 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-27 00:20:04.953029 | controller | skipping: Conditional result was False 2025-10-27 00:20:04.979204 | 2025-10-27 00:20:04.979346 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-27 00:20:05.004295 | controller | ok 2025-10-27 00:20:05.024290 | 2025-10-27 00:20:05.024437 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-27 00:20:05.295956 | controller -> localhost | ok 2025-10-27 00:20:05.307494 | 2025-10-27 00:20:05.307749 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-27 00:20:05.344825 | controller | ok 2025-10-27 00:20:05.367122 | controller | included: /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-27 00:20:05.378634 | 2025-10-27 00:20:05.378809 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-27 00:20:05.712175 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-27 00:20:05.712449 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/work/c34633e5beb943978c994c50c2047f47_id_ecdsa. 2025-10-27 00:20:05.712483 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/work/c34633e5beb943978c994c50c2047f47_id_ecdsa.pub. 2025-10-27 00:20:05.712520 | controller -> localhost | The key fingerprint is: 2025-10-27 00:20:05.712546 | controller -> localhost | SHA256:Ve6XeJfJIUtKXln7Pl1I0tWsO0Q6MDiitFDAP0Fpla4 zuul-build-sshkey 2025-10-27 00:20:05.712569 | controller -> localhost | The key's randomart image is: 2025-10-27 00:20:05.712592 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-27 00:20:05.712613 | controller -> localhost | | ..+oo.. . . oo| 2025-10-27 00:20:05.712634 | controller -> localhost | | o = o o oo .+.+| 2025-10-27 00:20:05.712656 | controller -> localhost | | = = . ..+oBo+ | 2025-10-27 00:20:05.712705 | controller -> localhost | | = . .o.*+*o=| 2025-10-27 00:20:05.712739 | controller -> localhost | | o S oo+==+| 2025-10-27 00:20:05.712763 | controller -> localhost | | E oooo| 2025-10-27 00:20:05.712786 | controller -> localhost | | oo| 2025-10-27 00:20:05.712808 | controller -> localhost | | .| 2025-10-27 00:20:05.712829 | controller -> localhost | | | 2025-10-27 00:20:05.712851 | controller -> localhost | +----[SHA256]-----+ 2025-10-27 00:20:05.712913 | controller -> localhost | ok: Runtime: 0:00:00.008605 2025-10-27 00:20:05.723355 | 2025-10-27 00:20:05.723509 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-27 00:20:05.746986 | controller | ok 2025-10-27 00:20:05.755477 | controller | included: /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-27 00:20:05.764588 | 2025-10-27 00:20:05.764668 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-27 00:20:05.781726 | controller | skipping: Conditional result was False 2025-10-27 00:20:05.789462 | 2025-10-27 00:20:05.789670 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-27 00:20:06.331513 | controller | changed 2025-10-27 00:20:06.337614 | 2025-10-27 00:20:06.337760 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-27 00:20:06.727426 | controller | ok 2025-10-27 00:20:06.733415 | 2025-10-27 00:20:06.733493 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-27 00:20:08.129761 | controller | changed 2025-10-27 00:20:08.137291 | 2025-10-27 00:20:08.137390 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-27 00:20:09.494367 | controller | changed 2025-10-27 00:20:09.505144 | 2025-10-27 00:20:09.505382 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-27 00:20:09.543031 | controller | skipping: Conditional result was False 2025-10-27 00:20:09.554203 | 2025-10-27 00:20:09.554349 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-27 00:20:09.847786 | controller -> localhost | changed 2025-10-27 00:20:09.929214 | 2025-10-27 00:20:09.929368 | TASK [add-build-sshkey : Add back temp key] 2025-10-27 00:20:10.302175 | controller -> localhost | Identity added: /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/work/c34633e5beb943978c994c50c2047f47_id_ecdsa (zuul-build-sshkey) 2025-10-27 00:20:10.302437 | controller -> localhost | ok: Runtime: 0:00:00.009339 2025-10-27 00:20:10.310106 | 2025-10-27 00:20:10.310198 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-27 00:20:10.675060 | controller | ok 2025-10-27 00:20:10.688194 | 2025-10-27 00:20:10.688377 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-27 00:20:10.747866 | controller | skipping: Conditional result was False 2025-10-27 00:20:10.769342 | 2025-10-27 00:20:10.769528 | TASK [include_role : remove-zuul-sshkey] 2025-10-27 00:20:10.796336 | controller | skipping: Conditional result was False 2025-10-27 00:20:10.804483 | 2025-10-27 00:20:10.804583 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-27 00:20:11.176230 | controller | ok: "logs" 2025-10-27 00:20:11.176764 | controller | ok: All items complete 2025-10-27 00:20:11.176837 | 2025-10-27 00:20:11.484731 | controller | ok: "artifacts" 2025-10-27 00:20:11.795521 | controller | ok: "docs" 2025-10-27 00:20:11.817104 | 2025-10-27 00:20:11.817291 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-27 00:20:12.186960 | controller | changed: "logs" 2025-10-27 00:20:12.491877 | controller | changed: "artifacts" 2025-10-27 00:20:12.827343 | controller | changed: "docs" 2025-10-27 00:20:12.886056 | 2025-10-27 00:20:12.886218 | PLAY RECAP 2025-10-27 00:20:12.886498 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-27 00:20:12.886758 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-27 00:20:12.886827 | 2025-10-27 00:20:13.110704 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-27 00:20:13.112133 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-27 00:20:13.901727 | 2025-10-27 00:20:13.901919 | PLAY [all] 2025-10-27 00:20:13.927453 | 2025-10-27 00:20:13.927657 | TASK [Install binary dependencies] 2025-10-27 00:20:13.991146 | controller | ok 2025-10-27 00:20:14.014460 | 2025-10-27 00:20:14.014612 | TASK [bindep : Include find tasks] 2025-10-27 00:20:14.046808 | controller | ok 2025-10-27 00:20:14.055821 | controller | included: /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-27 00:20:14.062618 | 2025-10-27 00:20:14.062713 | TASK [bindep : Look for bindep.txt] 2025-10-27 00:20:14.636496 | controller | ok 2025-10-27 00:20:14.652541 | 2025-10-27 00:20:14.652674 | TASK [bindep : Define bindep_file fact] 2025-10-27 00:20:14.678239 | controller | skipping: Conditional result was False 2025-10-27 00:20:14.686300 | 2025-10-27 00:20:14.686449 | TASK [bindep : Look for other-requirements.txt] 2025-10-27 00:20:15.005670 | controller | ok 2025-10-27 00:20:15.015616 | 2025-10-27 00:20:15.015742 | TASK [bindep : Define bindep_file fact] 2025-10-27 00:20:15.050867 | controller | skipping: Conditional result was False 2025-10-27 00:20:15.060087 | 2025-10-27 00:20:15.060202 | TASK [bindep : Look for bindep fallback file] 2025-10-27 00:20:15.086148 | controller | skipping: Conditional result was False 2025-10-27 00:20:15.100055 | 2025-10-27 00:20:15.100227 | TASK [bindep : Define bindep_file fact] 2025-10-27 00:20:15.128203 | controller | skipping: Conditional result was False 2025-10-27 00:20:15.142642 | 2025-10-27 00:20:15.142803 | TASK [bindep : Include bindep tasks] 2025-10-27 00:20:15.171695 | controller | skipping: Conditional result was False 2025-10-27 00:20:15.190785 | 2025-10-27 00:20:15.191065 | TASK [bindep : Include install tasks] 2025-10-27 00:20:15.217267 | controller | skipping: Conditional result was False 2025-10-27 00:20:15.225912 | 2025-10-27 00:20:15.226037 | LOOP [bindep : Include package tasks] 2025-10-27 00:20:15.299054 | 2025-10-27 00:20:15.299382 | TASK [Run test-setup role] 2025-10-27 00:20:15.323752 | controller | ok 2025-10-27 00:20:15.356971 | 2025-10-27 00:20:15.357232 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-27 00:20:15.674233 | controller | ok 2025-10-27 00:20:15.687024 | 2025-10-27 00:20:15.687219 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-27 00:20:15.870848 | controller | skipping: Conditional result was False 2025-10-27 00:20:15.904209 | 2025-10-27 00:20:15.904357 | PLAY RECAP 2025-10-27 00:20:15.904407 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-27 00:20:15.904429 | 2025-10-27 00:20:16.092758 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-27 00:20:16.093771 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-27 00:20:16.848246 | 2025-10-27 00:20:16.848468 | PLAY [controller] 2025-10-27 00:20:16.872183 | 2025-10-27 00:20:16.872345 | TASK [Create the /root directory] 2025-10-27 00:20:17.642222 | controller | ok 2025-10-27 00:20:17.657548 | 2025-10-27 00:20:17.657762 | TASK [Install glibc-langpack-en] 2025-10-27 00:20:25.833722 | controller | ok: Nothing to do 2025-10-27 00:20:25.846563 | 2025-10-27 00:20:25.846777 | TASK [Ensure controller directory exists] 2025-10-27 00:20:26.282622 | controller | changed 2025-10-27 00:20:26.290957 | 2025-10-27 00:20:26.291069 | TASK [Install container runtime] 2025-10-27 00:20:26.347007 | controller | ok 2025-10-27 00:20:26.400051 | 2025-10-27 00:20:26.400225 | LOOP [ensure-podman : Find distribution installation] 2025-10-27 00:20:26.433451 | controller | ok: "/var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-27 00:20:26.447119 | controller | included: /var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-27 00:20:26.458650 | 2025-10-27 00:20:26.458842 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-27 00:21:44.081229 | controller | changed 2025-10-27 00:21:44.091781 | 2025-10-27 00:21:44.091955 | TASK [ensure-podman : Fetch podman version] 2025-10-27 00:21:44.872536 | controller | Client: Podman Engine 2025-10-27 00:21:44.900468 | controller | Version: 4.6.2 2025-10-27 00:21:44.900518 | controller | API Version: 4.6.2 2025-10-27 00:21:44.900529 | controller | Go Version: go1.19.12 2025-10-27 00:21:44.900550 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-27 00:21:44.900756 | controller | OS/Arch: linux/amd64 2025-10-27 00:21:45.250023 | controller | ok: Runtime: 0:00:00.221333 2025-10-27 00:21:45.264432 | 2025-10-27 00:21:45.264640 | TASK [ensure-podman : Print podman version installed] 2025-10-27 00:21:45.308077 | Podman version: Client: Podman Engine 2025-10-27 00:21:45.308403 | Version: 4.6.2 2025-10-27 00:21:45.308470 | API Version: 4.6.2 2025-10-27 00:21:45.308525 | Go Version: go1.19.12 2025-10-27 00:21:45.308584 | Built: Mon Aug 28 19:38:31 2023 2025-10-27 00:21:45.308643 | OS/Arch: linux/amd64 2025-10-27 00:21:45.321956 | 2025-10-27 00:21:45.322154 | TASK [ensure-podman : Validate podman engine] 2025-10-27 00:21:45.473322 | controller | skipping: Conditional result was False 2025-10-27 00:21:45.487552 | 2025-10-27 00:21:45.487750 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-27 00:21:45.517362 | controller | skipping: Conditional result was False 2025-10-27 00:21:45.544333 | 2025-10-27 00:21:45.544816 | TASK [Ensure python3.8 is present] 2025-10-27 00:21:45.573421 | controller | skipping: Conditional result was False 2025-10-27 00:21:45.582700 | 2025-10-27 00:21:45.582815 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-27 00:21:45.611099 | controller | ok 2025-10-27 00:21:45.640550 | 2025-10-27 00:21:45.640744 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-27 00:21:49.531250 | controller | ok: Nothing to do 2025-10-27 00:21:49.544335 | 2025-10-27 00:21:49.544547 | TASK [our-ensure-python : Also install python3-devel] 2025-10-27 00:22:05.526069 | controller | changed 2025-10-27 00:22:05.536931 | 2025-10-27 00:22:05.537009 | TASK [Run ensure-virtualenv role] 2025-10-27 00:22:05.558502 | controller | ok 2025-10-27 00:22:05.578977 | 2025-10-27 00:22:05.579068 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-27 00:22:06.067478 | controller | /usr/bin/virtualenv 2025-10-27 00:22:06.216475 | controller | ok: Runtime: 0:00:00.005082 2025-10-27 00:22:06.226198 | 2025-10-27 00:22:06.226383 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-27 00:22:06.248698 | controller | skipping: Conditional result was False 2025-10-27 00:22:06.249031 | controller | ok: All items complete 2025-10-27 00:22:06.249064 | 2025-10-27 00:22:06.266008 | 2025-10-27 00:22:06.266179 | TASK [Find the full path of the Python interpreter] 2025-10-27 00:22:06.811960 | controller | /usr/bin/python3 2025-10-27 00:22:06.970240 | controller | ok 2025-10-27 00:22:06.977086 | 2025-10-27 00:22:06.977255 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-27 00:22:08.431868 | controller | created virtual environment CPython3.11.0.final.0-64 in 765ms 2025-10-27 00:22:08.479152 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-27 00:22:08.479212 | 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-27 00:22:08.479231 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-27 00:22:08.479255 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-27 00:22:08.625891 | controller | changed 2025-10-27 00:22:08.633154 | 2025-10-27 00:22:08.633249 | TASK [Set selinux package] 2025-10-27 00:22:08.672103 | controller | ok 2025-10-27 00:22:08.684489 | 2025-10-27 00:22:08.684632 | TASK [Set selinux package (Fedora)] 2025-10-27 00:22:08.730646 | controller | ok 2025-10-27 00:22:08.738041 | 2025-10-27 00:22:08.738159 | TASK [Install selinux into virtualenv] 2025-10-27 00:22:11.373708 | controller | Collecting selinux-please-lie-to-me 2025-10-27 00:22:11.464381 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-27 00:22:11.992635 | controller | Collecting setuptools<50.0.0 2025-10-27 00:22:12.006714 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-27 00:22:12.146436 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.1 MB/s eta 0:00:00 2025-10-27 00:22:12.296074 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-27 00:22:12.296495 | controller | Attempting uninstall: setuptools 2025-10-27 00:22:12.301489 | controller | Found existing installation: setuptools 62.6.0 2025-10-27 00:22:12.412684 | controller | Uninstalling setuptools-62.6.0: 2025-10-27 00:22:12.427276 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-27 00:22:13.169284 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-27 00:22:13.382363 | controller | 2025-10-27 00:22:13.589480 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-10-27 00:22:13.589531 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-27 00:22:13.933900 | controller | ok: Runtime: 0:00:04.346943 2025-10-27 00:22:13.949831 | 2025-10-27 00:22:13.950055 | TASK [Install pytest-forked into virtualenv] 2025-10-27 00:22:15.189116 | controller | Collecting pytest-forked 2025-10-27 00:22:15.281766 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-27 00:22:15.340737 | controller | Collecting py 2025-10-27 00:22:15.354982 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-27 00:22:15.393767 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.0 MB/s eta 0:00:00 2025-10-27 00:22:15.565777 | controller | Collecting pytest>=3.10 2025-10-27 00:22:15.580327 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-27 00:22:15.647715 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.5 MB/s eta 0:00:00 2025-10-27 00:22:15.699620 | controller | Collecting iniconfig>=1 2025-10-27 00:22:15.714287 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-27 00:22:15.780911 | controller | Collecting packaging>=20 2025-10-27 00:22:15.795377 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-27 00:22:15.808967 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 5.9 MB/s eta 0:00:00 2025-10-27 00:22:15.855520 | controller | Collecting pluggy<2,>=1.5 2025-10-27 00:22:15.869837 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-27 00:22:15.944779 | controller | Collecting pygments>=2.7.2 2025-10-27 00:22:15.959050 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-27 00:22:16.096515 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.1 MB/s eta 0:00:00 2025-10-27 00:22:16.227445 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-27 00:22:18.435271 | 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-27 00:22:18.451618 | controller | 2025-10-27 00:22:18.633501 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-10-27 00:22:18.633554 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-27 00:22:19.152292 | controller | ok: Runtime: 0:00:04.175216 2025-10-27 00:22:19.165290 | 2025-10-27 00:22:19.165431 | TASK [Update pip] 2025-10-27 00:22:20.508116 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-27 00:22:20.795944 | controller | Collecting pip 2025-10-27 00:22:20.901038 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-10-27 00:22:21.092788 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 9.6 MB/s eta 0:00:00 2025-10-27 00:22:21.258101 | controller | Installing collected packages: pip 2025-10-27 00:22:21.258414 | controller | Attempting uninstall: pip 2025-10-27 00:22:21.266449 | controller | Found existing installation: pip 22.2.2 2025-10-27 00:22:21.571890 | controller | Uninstalling pip-22.2.2: 2025-10-27 00:22:21.601843 | controller | Successfully uninstalled pip-22.2.2 2025-10-27 00:22:23.357913 | controller | Successfully installed pip-25.3 2025-10-27 00:22:23.828015 | controller | ok: Runtime: 0:00:03.791637 2025-10-27 00:22:23.838881 | 2025-10-27 00:22:23.839066 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-27 00:22:24.412806 | controller | changed 2025-10-27 00:22:24.418735 | 2025-10-27 00:22:24.418844 | TASK [Install ansible into virtualenv] 2025-10-27 00:22:25.480149 | controller | Processing ./src/github.com/ansible/ansible 2025-10-27 00:22:25.486664 | controller | Installing build dependencies: started 2025-10-27 00:22:27.295363 | controller | Installing build dependencies: finished with status 'done' 2025-10-27 00:22:28.814654 | controller | Getting requirements to build wheel: started 2025-10-27 00:22:28.814724 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-27 00:22:28.814879 | controller | Preparing metadata (pyproject.toml): started 2025-10-27 00:22:29.739662 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-27 00:22:29.744193 | 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-27 00:22:29.748997 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-27 00:22:30.068921 | controller | ERROR 2025-10-27 00:22:30.069324 | controller | { 2025-10-27 00:22:30.069392 | controller | "delta": "0:00:04.983177", 2025-10-27 00:22:30.069435 | controller | "end": "2025-10-27 00:22:29.886666", 2025-10-27 00:22:30.069472 | controller | "msg": "non-zero return code", 2025-10-27 00:22:30.069535 | controller | "rc": 1, 2025-10-27 00:22:30.069573 | controller | "start": "2025-10-27 00:22:24.903489" 2025-10-27 00:22:30.069607 | controller | } failure 2025-10-27 00:22:30.073335 | 2025-10-27 00:22:30.073442 | PLAY RECAP 2025-10-27 00:22:30.073554 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-27 00:22:30.073624 | 2025-10-27 00:22:30.218722 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-27 00:22:30.219829 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-27 00:22:30.885730 | 2025-10-27 00:22:30.885865 | PLAY [all] 2025-10-27 00:22:30.909472 | 2025-10-27 00:22:30.909647 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-27 00:22:31.770493 | controller | changed: non-zero return code 2025-10-27 00:22:31.784231 | 2025-10-27 00:22:31.784466 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-27 00:22:31.818765 | controller | skipping: Conditional result was False 2025-10-27 00:22:31.830270 | 2025-10-27 00:22:31.830420 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-27 00:22:31.873353 | 2025-10-27 00:22:31.873654 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-27 00:22:31.921059 | 2025-10-27 00:22:31.921419 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-27 00:22:31.948365 | controller | skipping: Conditional result was False 2025-10-27 00:22:31.958028 | 2025-10-27 00:22:31.958142 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-27 00:22:31.994614 | 2025-10-27 00:22:31.994957 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-27 00:22:32.021061 | controller | skipping: Conditional result was False 2025-10-27 00:22:32.030920 | 2025-10-27 00:22:32.031059 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-27 00:22:32.059923 | controller | skipping: Conditional result was False 2025-10-27 00:22:32.070471 | 2025-10-27 00:22:32.070636 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-27 00:22:32.097317 | controller | skipping: Conditional result was False 2025-10-27 00:22:32.133199 | 2025-10-27 00:22:32.133318 | PLAY RECAP 2025-10-27 00:22:32.133375 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-27 00:22:32.133402 | 2025-10-27 00:22:32.258786 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-27 00:22:32.259812 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-27 00:22:32.882822 | 2025-10-27 00:22:32.882963 | PLAY [all:!appliance*] 2025-10-27 00:22:32.908013 | 2025-10-27 00:22:32.908164 | TASK [unregister the node] 2025-10-27 00:22:33.048776 | controller | skipping: Conditional result was False 2025-10-27 00:22:33.057145 | 2025-10-27 00:22:33.057261 | TASK [include_role : fetch-output] 2025-10-27 00:22:33.113833 | controller | ok 2025-10-27 00:22:33.173575 | 2025-10-27 00:22:33.173744 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-27 00:22:33.240194 | controller | skipping: Conditional result was False 2025-10-27 00:22:33.248287 | 2025-10-27 00:22:33.248442 | TASK [fetch-output : Set log path for single node] 2025-10-27 00:22:33.293587 | controller | ok 2025-10-27 00:22:33.299255 | 2025-10-27 00:22:33.299369 | LOOP [fetch-output : Ensure local output dirs] 2025-10-27 00:22:33.746954 | controller -> localhost | ok: "/var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/work/logs" 2025-10-27 00:22:34.023737 | controller -> localhost | changed: "/var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/work/artifacts" 2025-10-27 00:22:34.280486 | controller -> localhost | changed: "/var/lib/zuul/builds/c34633e5beb943978c994c50c2047f47/work/docs" 2025-10-27 00:22:34.297247 | 2025-10-27 00:22:34.297400 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-27 00:22:35.561670 | controller | changed: 2025-10-27 00:22:35.561975 | controller | .d..t...... ./ 2025-10-27 00:22:35.562007 | controller | cd+++++++++ controller/ 2025-10-27 00:22:35.562043 | controller | changed: All items complete 2025-10-27 00:22:35.562064 | 2025-10-27 00:22:36.642055 | controller | changed: .d..t...... ./ 2025-10-27 00:22:37.763465 | controller | changed: .d..t...... ./ 2025-10-27 00:22:37.783259 | 2025-10-27 00:22:37.783419 | TASK [include_role : fetch-output-openshift] 2025-10-27 00:22:37.809954 | controller | skipping: Conditional result was False 2025-10-27 00:22:37.817193 | 2025-10-27 00:22:37.817321 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-27 00:22:37.863585 | controller | skipping: Conditional result was False 2025-10-27 00:22:37.876510 | controller | skipping: Conditional result was False 2025-10-27 00:22:37.911084 | 2025-10-27 00:22:37.911205 | PLAY [localhost] 2025-10-27 00:22:37.924133 | 2025-10-27 00:22:37.924231 | TASK [Run Zuul manifest role] 2025-10-27 00:22:37.951298 | localhost | ok 2025-10-27 00:22:37.979669 | 2025-10-27 00:22:37.979856 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-27 00:22:38.481470 | localhost | changed 2025-10-27 00:22:38.487100 | 2025-10-27 00:22:38.487170 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-27 00:22:38.519989 | localhost | ok 2025-10-27 00:22:38.529494 | 2025-10-27 00:22:38.529586 | TASK [Set zuul-log-path fact] 2025-10-27 00:22:38.549933 | localhost | ok 2025-10-27 00:22:38.564493 | 2025-10-27 00:22:38.564590 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-27 00:22:38.594587 | localhost | ok 2025-10-27 00:22:38.605061 | 2025-10-27 00:22:38.605289 | LOOP [Run upload-logs-swift role] 2025-10-27 00:22:38.641875 | localhost | Output suppressed because no_log was given 2025-10-27 00:22:38.680341 | 2025-10-27 00:22:38.680516 | TASK [Set zuul-log-path fact] 2025-10-27 00:22:38.706636 | localhost | skipping: Conditional result was False 2025-10-27 00:22:38.713215 | 2025-10-27 00:22:38.713351 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-27 00:22:39.189554 | localhost -> localhost | ok: Runtime: 0:00:00.007000 2025-10-27 00:22:39.195712 | 2025-10-27 00:22:39.195805 | TASK [upload-logs-swift : Upload logs to swift]