2025-10-25 00:11:38.003951 | Job console starting... 2025-10-25 00:11:38.018720 | Updating repositories 2025-10-25 00:11:38.211957 | Preparing job workspace 2025-10-25 00:11:42.272540 | Running Ansible setup... 2025-10-25 00:11:48.792085 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-25 00:11:49.434445 | 2025-10-25 00:11:49.434600 | PLAY [localhost] 2025-10-25 00:11:49.444056 | 2025-10-25 00:11:49.444175 | TASK [Gathering Facts] 2025-10-25 00:11:50.452285 | localhost | ok 2025-10-25 00:11:50.472538 | 2025-10-25 00:11:50.472703 | TASK [Setup log path fact] 2025-10-25 00:11:50.492833 | localhost | ok 2025-10-25 00:11:50.510817 | 2025-10-25 00:11:50.511136 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-25 00:11:50.540951 | localhost | ok 2025-10-25 00:11:50.552467 | 2025-10-25 00:11:50.552612 | TASK [emit-job-header : Print job information] 2025-10-25 00:11:50.593425 | # Job Information 2025-10-25 00:11:50.593617 | Ansible Version: 2.15.12 2025-10-25 00:11:50.593664 | Job: ansible-test-sanity-docker-devel 2025-10-25 00:11:50.593695 | Pipeline: periodic 2025-10-25 00:11:50.593724 | Executor: ze01.softwarefactory-project.io 2025-10-25 00:11:50.593751 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-25 00:11:50.593781 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/aa9/ansible/aa93310c2986463a99825a6fce7ec58c/ 2025-10-25 00:11:50.593809 | Event ID: 475785b7398d4c5089451ad6f27c677f 2025-10-25 00:11:50.599617 | 2025-10-25 00:11:50.599752 | LOOP [emit-job-header : Print node information] 2025-10-25 00:11:50.699883 | localhost | ok: 2025-10-25 00:11:50.700331 | localhost | # Node Information 2025-10-25 00:11:50.700417 | localhost | Inventory Hostname: controller 2025-10-25 00:11:50.700474 | localhost | Hostname: ip-172-16-75-46 2025-10-25 00:11:50.700576 | localhost | Username: zuul-worker 2025-10-25 00:11:50.700643 | localhost | Distro: Fedora 37 2025-10-25 00:11:50.700700 | localhost | Provider: ansible-us-east-2 2025-10-25 00:11:50.700755 | localhost | Region: us-east-2 2025-10-25 00:11:50.700795 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-25 00:11:50.700831 | localhost | Product Name: t3.small 2025-10-25 00:11:50.700867 | localhost | Interface IP: 3.145.193.40 2025-10-25 00:11:50.729256 | 2025-10-25 00:11:50.729482 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-25 00:11:51.244778 | localhost -> localhost | changed 2025-10-25 00:11:51.257978 | 2025-10-25 00:11:51.258176 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-25 00:11:52.163294 | localhost -> localhost | changed 2025-10-25 00:11:52.206582 | 2025-10-25 00:11:52.206750 | PLAY [all:!appliance*] 2025-10-25 00:11:52.237523 | 2025-10-25 00:11:52.237673 | TASK [include_role : start-zuul-console] 2025-10-25 00:11:52.273676 | controller | ok 2025-10-25 00:11:52.299826 | 2025-10-25 00:11:52.300076 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-25 00:11:52.947884 | controller | ok 2025-10-25 00:11:52.970440 | 2025-10-25 00:11:52.970589 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-25 00:11:54.345897 | controller | ok: Status code was -1 and not [200]: Request failed: 2025-10-25 00:11:54.359967 | 2025-10-25 00:11:54.360332 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-25 00:11:54.514091 | controller | skipping: Conditional result was False 2025-10-25 00:11:54.522505 | 2025-10-25 00:11:54.522633 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-25 00:11:54.557934 | controller | skipping: Conditional result was False 2025-10-25 00:11:54.565930 | 2025-10-25 00:11:54.566058 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-25 00:11:54.601284 | controller | skipping: Conditional result was False 2025-10-25 00:11:54.609110 | 2025-10-25 00:11:54.609210 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-25 00:11:54.644506 | controller | skipping: Conditional result was False 2025-10-25 00:11:54.652207 | 2025-10-25 00:11:54.652312 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-25 00:11:54.687530 | controller | skipping: Conditional result was False 2025-10-25 00:11:54.695391 | 2025-10-25 00:11:54.695504 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-25 00:11:54.720510 | controller | skipping: Conditional result was False 2025-10-25 00:11:54.735863 | 2025-10-25 00:11:54.735987 | TASK [Disable Fedora Modular] 2025-10-25 00:11:55.472956 | controller | changed 2025-10-25 00:11:55.485424 | 2025-10-25 00:11:55.485583 | TASK [Enable EPEL] 2025-10-25 00:11:55.512444 | controller | skipping: Conditional result was False 2025-10-25 00:11:55.518625 | 2025-10-25 00:11:55.518692 | TASK [Register the RHEL node] 2025-10-25 00:11:55.657102 | 2025-10-25 00:11:55.657371 | TASK [Show the subscription-manager status] 2025-10-25 00:11:55.819230 | controller | skipping: Conditional result was False 2025-10-25 00:11:55.875347 | 2025-10-25 00:11:55.875483 | TASK [Enable EPEL on RHEL] 2025-10-25 00:11:56.030942 | controller | skipping: Conditional result was False 2025-10-25 00:11:56.039937 | 2025-10-25 00:11:56.040134 | TASK [Install git and tox] 2025-10-25 00:13:30.681232 | controller | changed 2025-10-25 00:13:30.696463 | 2025-10-25 00:13:30.696617 | TASK [include_role : prepare-workspace] 2025-10-25 00:13:30.736124 | controller | ok 2025-10-25 00:13:30.771588 | 2025-10-25 00:13:30.771742 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-25 00:13:31.263849 | controller | ok 2025-10-25 00:13:31.271989 | 2025-10-25 00:13:31.272134 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-25 00:13:43.562962 | controller | Output suppressed because no_log was given 2025-10-25 00:13:43.577809 | 2025-10-25 00:13:43.577951 | TASK [include_role : prepare-workspace-openshift] 2025-10-25 00:13:43.605352 | controller | skipping: Conditional result was False 2025-10-25 00:13:43.636404 | 2025-10-25 00:13:43.636475 | PLAY [all:!appliance] 2025-10-25 00:13:43.679181 | 2025-10-25 00:13:43.679290 | TASK [Run add-build-sshkey role (RSA)] 2025-10-25 00:13:43.699611 | controller | ok 2025-10-25 00:13:43.714405 | 2025-10-25 00:13:43.714475 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-25 00:13:43.963725 | controller -> localhost | ok 2025-10-25 00:13:43.974192 | 2025-10-25 00:13:43.974275 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-25 00:13:44.005111 | controller | ok 2025-10-25 00:13:44.019945 | controller | included: /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-25 00:13:44.025576 | 2025-10-25 00:13:44.025639 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-25 00:13:44.563404 | controller -> localhost | Generating public/private rsa key pair. 2025-10-25 00:13:44.563640 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/work/aa93310c2986463a99825a6fce7ec58c_id_rsa. 2025-10-25 00:13:44.563679 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/work/aa93310c2986463a99825a6fce7ec58c_id_rsa.pub. 2025-10-25 00:13:44.563709 | controller -> localhost | The key fingerprint is: 2025-10-25 00:13:44.563751 | controller -> localhost | SHA256:C56S7YhWrAGUYmDG5gOjDE/b134oG9fm/Tr+gvY3gZA zuul-build-sshkey 2025-10-25 00:13:44.563787 | controller -> localhost | The key's randomart image is: 2025-10-25 00:13:44.563814 | controller -> localhost | +---[RSA 2048]----+ 2025-10-25 00:13:44.563879 | controller -> localhost | |+o. | 2025-10-25 00:13:44.563911 | controller -> localhost | |B*. | 2025-10-25 00:13:44.563938 | controller -> localhost | |@+ o . . | 2025-10-25 00:13:44.563964 | controller -> localhost | |o+o . . . E | 2025-10-25 00:13:44.563990 | controller -> localhost | | ... ...So . . | 2025-10-25 00:13:44.564057 | controller -> localhost | | . o+oo+.+ . . | 2025-10-25 00:13:44.564100 | controller -> localhost | | +o +=.+ o . | 2025-10-25 00:13:44.564131 | controller -> localhost | | o. +. + + o | 2025-10-25 00:13:44.564159 | controller -> localhost | | .. . . . o+Bo. | 2025-10-25 00:13:44.564189 | controller -> localhost | +----[SHA256]-----+ 2025-10-25 00:13:44.564255 | controller -> localhost | ok: Runtime: 0:00:00.156840 2025-10-25 00:13:44.574782 | 2025-10-25 00:13:44.574916 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-25 00:13:44.603769 | controller | ok 2025-10-25 00:13:44.616057 | controller | included: /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-25 00:13:44.628338 | 2025-10-25 00:13:44.628472 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-25 00:13:44.652886 | controller | skipping: Conditional result was False 2025-10-25 00:13:44.660043 | 2025-10-25 00:13:44.660151 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-25 00:13:46.530205 | controller | changed 2025-10-25 00:13:46.544988 | 2025-10-25 00:13:46.545420 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-25 00:13:47.027261 | controller | ok 2025-10-25 00:13:47.039981 | 2025-10-25 00:13:47.040148 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-25 00:13:48.548637 | controller | changed 2025-10-25 00:13:48.561718 | 2025-10-25 00:13:48.561853 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-25 00:13:49.980554 | controller | changed 2025-10-25 00:13:49.999847 | 2025-10-25 00:13:50.000085 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-25 00:13:50.029117 | controller | skipping: Conditional result was False 2025-10-25 00:13:50.045589 | 2025-10-25 00:13:50.045814 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-25 00:13:50.492905 | controller -> localhost | changed 2025-10-25 00:13:50.519648 | 2025-10-25 00:13:50.519874 | TASK [add-build-sshkey : Add back temp key] 2025-10-25 00:13:50.863194 | controller -> localhost | Identity added: /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/work/aa93310c2986463a99825a6fce7ec58c_id_rsa (zuul-build-sshkey) 2025-10-25 00:13:50.863463 | controller -> localhost | ok: Runtime: 0:00:00.012965 2025-10-25 00:13:50.872132 | 2025-10-25 00:13:50.872219 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-25 00:13:51.411252 | controller | ok 2025-10-25 00:13:51.417282 | 2025-10-25 00:13:51.417363 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-25 00:13:51.442159 | controller | skipping: Conditional result was False 2025-10-25 00:13:51.452713 | 2025-10-25 00:13:51.452803 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-25 00:13:51.482283 | controller | ok 2025-10-25 00:13:51.498219 | 2025-10-25 00:13:51.498324 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-25 00:13:51.810894 | controller -> localhost | ok 2025-10-25 00:13:51.819418 | 2025-10-25 00:13:51.819539 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-25 00:13:51.854558 | controller | ok 2025-10-25 00:13:51.869541 | controller | included: /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-25 00:13:51.878493 | 2025-10-25 00:13:51.878636 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-25 00:13:52.150764 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-25 00:13:52.151059 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/work/aa93310c2986463a99825a6fce7ec58c_id_ecdsa. 2025-10-25 00:13:52.151106 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/work/aa93310c2986463a99825a6fce7ec58c_id_ecdsa.pub. 2025-10-25 00:13:52.151147 | controller -> localhost | The key fingerprint is: 2025-10-25 00:13:52.151177 | controller -> localhost | SHA256:G/53U022HXNjCUSpjLSER2an+JcTJielz5oIWzK8IDk zuul-build-sshkey 2025-10-25 00:13:52.151209 | controller -> localhost | The key's randomart image is: 2025-10-25 00:13:52.151237 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-25 00:13:52.151288 | controller -> localhost | | o+ ooo. | 2025-10-25 00:13:52.151317 | controller -> localhost | | .++= o | 2025-10-25 00:13:52.151344 | controller -> localhost | | .+=++. . .| 2025-10-25 00:13:52.151370 | controller -> localhost | | . . .oBoo *+| 2025-10-25 00:13:52.151397 | controller -> localhost | | E . = .S. * .oO| 2025-10-25 00:13:52.151423 | controller -> localhost | | o . B..o+ . .+| 2025-10-25 00:13:52.151449 | controller -> localhost | | o .oo . | 2025-10-25 00:13:52.151474 | controller -> localhost | | . . o | 2025-10-25 00:13:52.151499 | controller -> localhost | | .. . . | 2025-10-25 00:13:52.151523 | controller -> localhost | +----[SHA256]-----+ 2025-10-25 00:13:52.151588 | controller -> localhost | ok: Runtime: 0:00:00.009554 2025-10-25 00:13:52.159944 | 2025-10-25 00:13:52.160045 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-25 00:13:52.183662 | controller | ok 2025-10-25 00:13:52.193047 | controller | included: /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-25 00:13:52.205074 | 2025-10-25 00:13:52.205178 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-25 00:13:52.230547 | controller | skipping: Conditional result was False 2025-10-25 00:13:52.238332 | 2025-10-25 00:13:52.238440 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-25 00:13:52.750464 | controller | changed 2025-10-25 00:13:52.762110 | 2025-10-25 00:13:52.762246 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-25 00:13:53.177668 | controller | ok 2025-10-25 00:13:53.189761 | 2025-10-25 00:13:53.189931 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-25 00:13:54.591455 | controller | changed 2025-10-25 00:13:54.597223 | 2025-10-25 00:13:54.597294 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-25 00:13:55.987765 | controller | changed 2025-10-25 00:13:55.993732 | 2025-10-25 00:13:55.993815 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-25 00:13:56.018728 | controller | skipping: Conditional result was False 2025-10-25 00:13:56.031511 | 2025-10-25 00:13:56.031699 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-25 00:13:56.328052 | controller -> localhost | changed 2025-10-25 00:13:56.340491 | 2025-10-25 00:13:56.340578 | TASK [add-build-sshkey : Add back temp key] 2025-10-25 00:13:56.708465 | controller -> localhost | Identity added: /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/work/aa93310c2986463a99825a6fce7ec58c_id_ecdsa (zuul-build-sshkey) 2025-10-25 00:13:56.708650 | controller -> localhost | ok: Runtime: 0:00:00.011035 2025-10-25 00:13:56.714727 | 2025-10-25 00:13:56.714789 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-25 00:13:57.079707 | controller | ok 2025-10-25 00:13:57.093390 | 2025-10-25 00:13:57.093592 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-25 00:13:57.121257 | controller | skipping: Conditional result was False 2025-10-25 00:13:57.143524 | 2025-10-25 00:13:57.143767 | TASK [include_role : remove-zuul-sshkey] 2025-10-25 00:13:57.181506 | controller | skipping: Conditional result was False 2025-10-25 00:13:57.190480 | 2025-10-25 00:13:57.190638 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-25 00:13:57.574721 | controller | ok: "logs" 2025-10-25 00:13:57.575188 | controller | ok: All items complete 2025-10-25 00:13:57.575250 | 2025-10-25 00:13:57.913488 | controller | ok: "artifacts" 2025-10-25 00:13:58.224064 | controller | ok: "docs" 2025-10-25 00:13:58.240086 | 2025-10-25 00:13:58.240286 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-25 00:13:58.645240 | controller | changed: "logs" 2025-10-25 00:13:58.981778 | controller | changed: "artifacts" 2025-10-25 00:13:59.334497 | controller | changed: "docs" 2025-10-25 00:13:59.401049 | 2025-10-25 00:13:59.401191 | PLAY RECAP 2025-10-25 00:13:59.401255 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-25 00:13:59.401294 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-25 00:13:59.401319 | 2025-10-25 00:13:59.522840 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-25 00:13:59.523710 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-25 00:14:00.147430 | 2025-10-25 00:14:00.147564 | PLAY [all] 2025-10-25 00:14:00.169958 | 2025-10-25 00:14:00.170120 | TASK [Install binary dependencies] 2025-10-25 00:14:00.223955 | controller | ok 2025-10-25 00:14:00.249738 | 2025-10-25 00:14:00.249885 | TASK [bindep : Include find tasks] 2025-10-25 00:14:00.280408 | controller | ok 2025-10-25 00:14:00.288649 | controller | included: /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-25 00:14:00.295440 | 2025-10-25 00:14:00.295533 | TASK [bindep : Look for bindep.txt] 2025-10-25 00:14:00.871409 | controller | ok 2025-10-25 00:14:00.885426 | 2025-10-25 00:14:00.885612 | TASK [bindep : Define bindep_file fact] 2025-10-25 00:14:00.902656 | controller | skipping: Conditional result was False 2025-10-25 00:14:00.912154 | 2025-10-25 00:14:00.912299 | TASK [bindep : Look for other-requirements.txt] 2025-10-25 00:14:01.406171 | controller | ok 2025-10-25 00:14:01.414539 | 2025-10-25 00:14:01.414660 | TASK [bindep : Define bindep_file fact] 2025-10-25 00:14:01.441939 | controller | skipping: Conditional result was False 2025-10-25 00:14:01.451989 | 2025-10-25 00:14:01.452228 | TASK [bindep : Look for bindep fallback file] 2025-10-25 00:14:01.479962 | controller | skipping: Conditional result was False 2025-10-25 00:14:01.488301 | 2025-10-25 00:14:01.488464 | TASK [bindep : Define bindep_file fact] 2025-10-25 00:14:01.515343 | controller | skipping: Conditional result was False 2025-10-25 00:14:01.528725 | 2025-10-25 00:14:01.528897 | TASK [bindep : Include bindep tasks] 2025-10-25 00:14:01.555405 | controller | skipping: Conditional result was False 2025-10-25 00:14:01.565157 | 2025-10-25 00:14:01.565330 | TASK [bindep : Include install tasks] 2025-10-25 00:14:01.592738 | controller | skipping: Conditional result was False 2025-10-25 00:14:01.606585 | 2025-10-25 00:14:01.606757 | LOOP [bindep : Include package tasks] 2025-10-25 00:14:01.683320 | 2025-10-25 00:14:01.683531 | TASK [Run test-setup role] 2025-10-25 00:14:01.706932 | controller | ok 2025-10-25 00:14:01.735451 | 2025-10-25 00:14:01.735618 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-25 00:14:02.611433 | controller | ok 2025-10-25 00:14:02.626365 | 2025-10-25 00:14:02.626562 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-25 00:14:02.788982 | controller | skipping: Conditional result was False 2025-10-25 00:14:02.825089 | 2025-10-25 00:14:02.825210 | PLAY RECAP 2025-10-25 00:14:02.825273 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-25 00:14:02.825304 | 2025-10-25 00:14:02.947088 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-25 00:14:02.948091 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-25 00:14:03.556181 | 2025-10-25 00:14:03.556347 | PLAY [controller] 2025-10-25 00:14:03.576785 | 2025-10-25 00:14:03.576932 | TASK [Create the /root directory] 2025-10-25 00:14:04.340907 | controller | ok 2025-10-25 00:14:04.350067 | 2025-10-25 00:14:04.350282 | TASK [Install glibc-langpack-en] 2025-10-25 00:14:12.534317 | controller | ok: Nothing to do 2025-10-25 00:14:12.547065 | 2025-10-25 00:14:12.547208 | TASK [Ensure controller directory exists] 2025-10-25 00:14:12.971414 | controller | changed 2025-10-25 00:14:12.984183 | 2025-10-25 00:14:12.984344 | TASK [Install container runtime] 2025-10-25 00:14:13.063982 | controller | ok 2025-10-25 00:14:13.123956 | 2025-10-25 00:14:13.124406 | LOOP [ensure-podman : Find distribution installation] 2025-10-25 00:14:13.155874 | controller | ok: "/var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-25 00:14:13.169942 | controller | included: /var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-25 00:14:13.179486 | 2025-10-25 00:14:13.179579 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-25 00:15:28.807698 | controller | changed 2025-10-25 00:15:28.823890 | 2025-10-25 00:15:28.824069 | TASK [ensure-podman : Fetch podman version] 2025-10-25 00:15:29.520625 | controller | Client: Podman Engine 2025-10-25 00:15:29.546169 | controller | Version: 4.6.2 2025-10-25 00:15:29.546209 | controller | API Version: 4.6.2 2025-10-25 00:15:29.546216 | controller | Go Version: go1.19.12 2025-10-25 00:15:29.546234 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-25 00:15:29.546240 | controller | OS/Arch: linux/amd64 2025-10-25 00:15:29.971418 | controller | ok: Runtime: 0:00:00.215183 2025-10-25 00:15:29.978052 | 2025-10-25 00:15:29.978150 | TASK [ensure-podman : Print podman version installed] 2025-10-25 00:15:30.017510 | Podman version: Client: Podman Engine 2025-10-25 00:15:30.017773 | Version: 4.6.2 2025-10-25 00:15:30.017835 | API Version: 4.6.2 2025-10-25 00:15:30.017880 | Go Version: go1.19.12 2025-10-25 00:15:30.017920 | Built: Mon Aug 28 19:38:31 2023 2025-10-25 00:15:30.017961 | OS/Arch: linux/amd64 2025-10-25 00:15:30.030072 | 2025-10-25 00:15:30.030269 | TASK [ensure-podman : Validate podman engine] 2025-10-25 00:15:30.193503 | controller | skipping: Conditional result was False 2025-10-25 00:15:30.205919 | 2025-10-25 00:15:30.206123 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-25 00:15:30.233724 | controller | skipping: Conditional result was False 2025-10-25 00:15:30.257303 | 2025-10-25 00:15:30.257482 | TASK [Ensure python3.8 is present] 2025-10-25 00:15:30.274746 | controller | skipping: Conditional result was False 2025-10-25 00:15:30.289985 | 2025-10-25 00:15:30.290286 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-25 00:15:30.320485 | controller | ok 2025-10-25 00:15:30.344838 | 2025-10-25 00:15:30.344956 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-25 00:15:34.015788 | controller | ok: Nothing to do 2025-10-25 00:15:34.031064 | 2025-10-25 00:15:34.031289 | TASK [our-ensure-python : Also install python3-devel] 2025-10-25 00:15:47.320280 | controller | changed 2025-10-25 00:15:47.341693 | 2025-10-25 00:15:47.341836 | TASK [Run ensure-virtualenv role] 2025-10-25 00:15:47.365194 | controller | ok 2025-10-25 00:15:47.398886 | 2025-10-25 00:15:47.399061 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-25 00:15:47.781226 | controller | /usr/bin/virtualenv 2025-10-25 00:15:48.040770 | controller | ok: Runtime: 0:00:00.004242 2025-10-25 00:15:48.050250 | 2025-10-25 00:15:48.050399 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-25 00:15:48.085224 | controller | skipping: Conditional result was False 2025-10-25 00:15:48.085484 | controller | ok: All items complete 2025-10-25 00:15:48.085512 | 2025-10-25 00:15:48.104672 | 2025-10-25 00:15:48.104822 | TASK [Find the full path of the Python interpreter] 2025-10-25 00:15:48.595808 | controller | /usr/bin/python3 2025-10-25 00:15:48.784750 | controller | ok 2025-10-25 00:15:48.799802 | 2025-10-25 00:15:48.800004 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-25 00:15:50.814346 | controller | created virtual environment CPython3.11.0.final.0-64 in 735ms 2025-10-25 00:15:50.859001 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-25 00:15:50.859057 | 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-25 00:15:50.859077 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-25 00:15:50.859100 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-25 00:15:50.970893 | controller | changed 2025-10-25 00:15:50.984736 | 2025-10-25 00:15:50.984913 | TASK [Set selinux package] 2025-10-25 00:15:51.026662 | controller | ok 2025-10-25 00:15:51.039560 | 2025-10-25 00:15:51.039749 | TASK [Set selinux package (Fedora)] 2025-10-25 00:15:51.086094 | controller | ok 2025-10-25 00:15:51.095044 | 2025-10-25 00:15:51.095196 | TASK [Install selinux into virtualenv] 2025-10-25 00:15:53.667184 | controller | Collecting selinux-please-lie-to-me 2025-10-25 00:15:53.754385 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-25 00:15:54.284591 | controller | Collecting setuptools<50.0.0 2025-10-25 00:15:54.298025 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-25 00:15:54.420721 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00 2025-10-25 00:15:54.578035 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-25 00:15:54.578442 | controller | Attempting uninstall: setuptools 2025-10-25 00:15:54.583413 | controller | Found existing installation: setuptools 62.6.0 2025-10-25 00:15:54.695175 | controller | Uninstalling setuptools-62.6.0: 2025-10-25 00:15:54.710453 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-25 00:15:55.443047 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-25 00:15:55.646251 | controller | 2025-10-25 00:15:55.855131 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-25 00:15:55.855175 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-25 00:15:56.265346 | controller | ok: Runtime: 0:00:04.279849 2025-10-25 00:15:56.272057 | 2025-10-25 00:15:56.272145 | TASK [Install pytest-forked into virtualenv] 2025-10-25 00:15:57.450542 | controller | Collecting pytest-forked 2025-10-25 00:15:57.536950 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-25 00:15:57.597476 | controller | Collecting py 2025-10-25 00:15:57.610152 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-25 00:15:57.647013 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00 2025-10-25 00:15:57.820428 | controller | Collecting pytest>=3.10 2025-10-25 00:15:57.832407 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-25 00:15:57.894298 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 6.2 MB/s eta 0:00:00 2025-10-25 00:15:57.948641 | controller | Collecting iniconfig>=1 2025-10-25 00:15:57.961184 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-25 00:15:58.028860 | controller | Collecting packaging>=20 2025-10-25 00:15:58.040476 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-25 00:15:58.052584 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 6.9 MB/s eta 0:00:00 2025-10-25 00:15:58.101587 | controller | Collecting pluggy<2,>=1.5 2025-10-25 00:15:58.111815 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-25 00:15:58.184821 | controller | Collecting pygments>=2.7.2 2025-10-25 00:15:58.196492 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-25 00:15:58.313793 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 10.7 MB/s eta 0:00:00 2025-10-25 00:15:58.443008 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-25 00:16:00.710394 | 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-25 00:16:00.726517 | controller | 2025-10-25 00:16:00.917143 | controller | [notice] A new release of pip available: 22.2.2 -> 25.2 2025-10-25 00:16:00.917194 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-25 00:16:01.465253 | controller | ok: Runtime: 0:00:04.189707 2025-10-25 00:16:01.478224 | 2025-10-25 00:16:01.478389 | TASK [Update pip] 2025-10-25 00:16:02.619320 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-25 00:16:02.912851 | controller | Collecting pip 2025-10-25 00:16:03.016322 | controller | Downloading pip-25.2-py3-none-any.whl (1.8 MB) 2025-10-25 00:16:03.124759 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 16.9 MB/s eta 0:00:00 2025-10-25 00:16:03.247862 | controller | Installing collected packages: pip 2025-10-25 00:16:03.248276 | controller | Attempting uninstall: pip 2025-10-25 00:16:03.252708 | controller | Found existing installation: pip 22.2.2 2025-10-25 00:16:03.510484 | controller | Uninstalling pip-22.2.2: 2025-10-25 00:16:03.540258 | controller | Successfully uninstalled pip-22.2.2 2025-10-25 00:16:05.409930 | controller | Successfully installed pip-25.2 2025-10-25 00:16:05.667071 | controller | ok: Runtime: 0:00:03.570413 2025-10-25 00:16:05.680624 | 2025-10-25 00:16:05.680757 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-25 00:16:06.201492 | controller | changed 2025-10-25 00:16:06.219902 | 2025-10-25 00:16:06.220171 | TASK [Install ansible into virtualenv] 2025-10-25 00:16:07.344076 | controller | Processing ./src/github.com/ansible/ansible 2025-10-25 00:16:07.350666 | controller | Installing build dependencies: started 2025-10-25 00:16:09.095305 | controller | Installing build dependencies: finished with status 'done' 2025-10-25 00:16:10.597454 | controller | Getting requirements to build wheel: started 2025-10-25 00:16:10.597518 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-25 00:16:10.599029 | controller | Preparing metadata (pyproject.toml): started 2025-10-25 00:16:11.519601 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-25 00:16:11.522626 | 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-25 00:16:11.527492 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-25 00:16:11.896786 | controller | ERROR 2025-10-25 00:16:11.896977 | controller | { 2025-10-25 00:16:11.897010 | controller | "delta": "0:00:04.934501", 2025-10-25 00:16:11.897057 | controller | "end": "2025-10-25 00:16:11.660573", 2025-10-25 00:16:11.897093 | controller | "msg": "non-zero return code", 2025-10-25 00:16:11.897123 | controller | "rc": 1, 2025-10-25 00:16:11.897144 | controller | "start": "2025-10-25 00:16:06.726072" 2025-10-25 00:16:11.897161 | controller | } failure 2025-10-25 00:16:11.898667 | 2025-10-25 00:16:11.898716 | PLAY RECAP 2025-10-25 00:16:11.898758 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-25 00:16:11.898779 | 2025-10-25 00:16:12.004694 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-25 00:16:12.005872 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-25 00:16:12.759996 | 2025-10-25 00:16:12.760214 | PLAY [all] 2025-10-25 00:16:12.786221 | 2025-10-25 00:16:12.786418 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-25 00:16:13.583117 | controller | changed: non-zero return code 2025-10-25 00:16:13.590807 | 2025-10-25 00:16:13.590935 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-25 00:16:13.605881 | controller | skipping: Conditional result was False 2025-10-25 00:16:13.613099 | 2025-10-25 00:16:13.613206 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-25 00:16:13.644856 | 2025-10-25 00:16:13.645059 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-25 00:16:13.676566 | 2025-10-25 00:16:13.676746 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-25 00:16:13.691982 | controller | skipping: Conditional result was False 2025-10-25 00:16:13.699438 | 2025-10-25 00:16:13.699526 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-25 00:16:13.732141 | 2025-10-25 00:16:13.732315 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-25 00:16:13.747625 | controller | skipping: Conditional result was False 2025-10-25 00:16:13.754523 | 2025-10-25 00:16:13.754630 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-25 00:16:13.769537 | controller | skipping: Conditional result was False 2025-10-25 00:16:13.776491 | 2025-10-25 00:16:13.776575 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-25 00:16:13.801083 | controller | skipping: Conditional result was False 2025-10-25 00:16:13.836380 | 2025-10-25 00:16:13.836504 | PLAY RECAP 2025-10-25 00:16:13.836562 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-25 00:16:13.836592 | 2025-10-25 00:16:13.992735 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-25 00:16:13.993842 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-25 00:16:14.613303 | 2025-10-25 00:16:14.613436 | PLAY [all:!appliance*] 2025-10-25 00:16:14.645592 | 2025-10-25 00:16:14.645726 | TASK [unregister the node] 2025-10-25 00:16:14.779264 | controller | skipping: Conditional result was False 2025-10-25 00:16:14.785479 | 2025-10-25 00:16:14.785586 | TASK [include_role : fetch-output] 2025-10-25 00:16:14.815171 | controller | ok 2025-10-25 00:16:14.834437 | 2025-10-25 00:16:14.834560 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-25 00:16:14.879205 | controller | skipping: Conditional result was False 2025-10-25 00:16:14.885414 | 2025-10-25 00:16:14.885497 | TASK [fetch-output : Set log path for single node] 2025-10-25 00:16:14.914784 | controller | ok 2025-10-25 00:16:14.920452 | 2025-10-25 00:16:14.920537 | LOOP [fetch-output : Ensure local output dirs] 2025-10-25 00:16:15.352983 | controller -> localhost | ok: "/var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/work/logs" 2025-10-25 00:16:15.621188 | controller -> localhost | changed: "/var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/work/artifacts" 2025-10-25 00:16:15.883348 | controller -> localhost | changed: "/var/lib/zuul/builds/aa93310c2986463a99825a6fce7ec58c/work/docs" 2025-10-25 00:16:15.894041 | 2025-10-25 00:16:15.894175 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-25 00:16:17.157095 | controller | changed: 2025-10-25 00:16:17.157486 | controller | .d..t...... ./ 2025-10-25 00:16:17.157535 | controller | cd+++++++++ controller/ 2025-10-25 00:16:17.157587 | controller | changed: All items complete 2025-10-25 00:16:17.157614 | 2025-10-25 00:16:18.175317 | controller | changed: .d..t...... ./ 2025-10-25 00:16:19.225269 | controller | changed: .d..t...... ./ 2025-10-25 00:16:19.248761 | 2025-10-25 00:16:19.248902 | TASK [include_role : fetch-output-openshift] 2025-10-25 00:16:19.273799 | controller | skipping: Conditional result was False 2025-10-25 00:16:19.281986 | 2025-10-25 00:16:19.282156 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-25 00:16:19.327960 | controller | skipping: Conditional result was False 2025-10-25 00:16:19.343614 | controller | skipping: Conditional result was False 2025-10-25 00:16:19.376171 | 2025-10-25 00:16:19.376336 | PLAY [localhost] 2025-10-25 00:16:19.397435 | 2025-10-25 00:16:19.397571 | TASK [Run Zuul manifest role] 2025-10-25 00:16:19.418423 | localhost | ok 2025-10-25 00:16:19.436220 | 2025-10-25 00:16:19.436293 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-25 00:16:19.833164 | localhost | changed 2025-10-25 00:16:19.838003 | 2025-10-25 00:16:19.838101 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-25 00:16:19.866241 | localhost | ok 2025-10-25 00:16:19.874418 | 2025-10-25 00:16:19.874513 | TASK [Set zuul-log-path fact] 2025-10-25 00:16:19.894789 | localhost | ok 2025-10-25 00:16:19.912500 | 2025-10-25 00:16:19.912671 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-25 00:16:19.944174 | localhost | ok 2025-10-25 00:16:19.956744 | 2025-10-25 00:16:19.956890 | LOOP [Run upload-logs-swift role] 2025-10-25 00:16:19.995534 | localhost | Output suppressed because no_log was given 2025-10-25 00:16:20.035494 | 2025-10-25 00:16:20.035636 | TASK [Set zuul-log-path fact] 2025-10-25 00:16:20.070639 | localhost | skipping: Conditional result was False 2025-10-25 00:16:20.079205 | 2025-10-25 00:16:20.079343 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-25 00:16:20.544895 | localhost -> localhost | ok: Runtime: 0:00:00.006167 2025-10-25 00:16:20.551869 | 2025-10-25 00:16:20.551950 | TASK [upload-logs-swift : Upload logs to swift]