2025-10-29 00:17:46.017036 | Job console starting... 2025-10-29 00:17:46.029122 | Updating repositories 2025-10-29 00:17:46.144438 | Preparing job workspace 2025-10-29 00:17:51.230435 | Running Ansible setup... 2025-10-29 00:17:57.256366 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-29 00:17:57.960015 | 2025-10-29 00:17:57.960173 | PLAY [localhost] 2025-10-29 00:17:57.970067 | 2025-10-29 00:17:57.970192 | TASK [Gathering Facts] 2025-10-29 00:17:59.082079 | localhost | ok 2025-10-29 00:17:59.106606 | 2025-10-29 00:17:59.106807 | TASK [Setup log path fact] 2025-10-29 00:17:59.127458 | localhost | ok 2025-10-29 00:17:59.164039 | 2025-10-29 00:17:59.164618 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-29 00:17:59.204141 | localhost | ok 2025-10-29 00:17:59.217166 | 2025-10-29 00:17:59.217280 | TASK [emit-job-header : Print job information] 2025-10-29 00:17:59.255760 | # Job Information 2025-10-29 00:17:59.256272 | Ansible Version: 2.15.12 2025-10-29 00:17:59.256316 | Job: ansible-test-sanity-docker-milestone 2025-10-29 00:17:59.256339 | Pipeline: periodic 2025-10-29 00:17:59.256357 | Executor: ze04.softwarefactory-project.io 2025-10-29 00:17:59.256375 | Triggered by: https://github.com/ansible-collections/ansible.network 2025-10-29 00:17:59.256398 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/30e/ansible/30ea7e71e4694ac8a7c6d0bc0c1b63ba/ 2025-10-29 00:17:59.256417 | Event ID: a4ea198b67664ad8b8b738cb49a7abfb 2025-10-29 00:17:59.260609 | 2025-10-29 00:17:59.260708 | LOOP [emit-job-header : Print node information] 2025-10-29 00:17:59.376596 | localhost | ok: 2025-10-29 00:17:59.376824 | localhost | # Node Information 2025-10-29 00:17:59.376855 | localhost | Inventory Hostname: controller 2025-10-29 00:17:59.376877 | localhost | Hostname: ip-172-16-120-142 2025-10-29 00:17:59.376895 | localhost | Username: zuul-worker 2025-10-29 00:17:59.376915 | localhost | Distro: Fedora 37 2025-10-29 00:17:59.376933 | localhost | Provider: ansible-us-east-2 2025-10-29 00:17:59.376951 | localhost | Region: us-east-2 2025-10-29 00:17:59.376968 | localhost | Label: ansible-fedora-37-1vcpu 2025-10-29 00:17:59.376985 | localhost | Product Name: t3.small 2025-10-29 00:17:59.377002 | localhost | Interface IP: 3.134.244.200 2025-10-29 00:17:59.395583 | 2025-10-29 00:17:59.395681 | TASK [log-inventory : Ensure Zuul Ansible directory exists] 2025-10-29 00:17:59.902263 | localhost -> localhost | changed 2025-10-29 00:17:59.911910 | 2025-10-29 00:17:59.912060 | TASK [log-inventory : Copy ansible inventory to logs dir] 2025-10-29 00:18:00.960124 | localhost -> localhost | changed 2025-10-29 00:18:01.000092 | 2025-10-29 00:18:01.000247 | PLAY [all:!appliance*] 2025-10-29 00:18:01.029199 | 2025-10-29 00:18:01.029351 | TASK [include_role : start-zuul-console] 2025-10-29 00:18:01.061926 | controller | ok 2025-10-29 00:18:01.089941 | 2025-10-29 00:18:01.090094 | TASK [start-zuul-console : Start zuul_console daemon.] 2025-10-29 00:18:02.175602 | controller | ok 2025-10-29 00:18:02.187245 | 2025-10-29 00:18:02.187364 | TASK [use-our-mirror : Retrieve the IP address] 2025-10-29 00:18:03.959945 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found 2025-10-29 00:18:03.972080 | 2025-10-29 00:18:03.972211 | TASK [use-our-mirror : Ensure the registry service is running on the mirror] 2025-10-29 00:18:04.123109 | controller | skipping: Conditional result was False 2025-10-29 00:18:04.140034 | 2025-10-29 00:18:04.140231 | TASK [use-our-mirror : Write the IP in /etc/hosts] 2025-10-29 00:18:04.158483 | controller | skipping: Conditional result was False 2025-10-29 00:18:04.165264 | 2025-10-29 00:18:04.165340 | TASK [use-our-mirror : Create the podman configuration directory] 2025-10-29 00:18:04.190061 | controller | skipping: Conditional result was False 2025-10-29 00:18:04.198029 | 2025-10-29 00:18:04.198105 | TASK [use-our-mirror : Copy the podman configuration] 2025-10-29 00:18:04.223916 | controller | skipping: Conditional result was False 2025-10-29 00:18:04.235862 | 2025-10-29 00:18:04.235998 | TASK [use-our-mirror : Copy the Yum configuration (main)] 2025-10-29 00:18:04.253297 | controller | skipping: Conditional result was False 2025-10-29 00:18:04.263437 | 2025-10-29 00:18:04.263541 | TASK [use-our-mirror : Copy the Yum configuration (update)] 2025-10-29 00:18:04.289245 | controller | skipping: Conditional result was False 2025-10-29 00:18:04.306798 | 2025-10-29 00:18:04.306964 | TASK [Disable Fedora Modular] 2025-10-29 00:18:05.071862 | controller | changed 2025-10-29 00:18:05.078631 | 2025-10-29 00:18:05.078783 | TASK [Enable EPEL] 2025-10-29 00:18:05.103750 | controller | skipping: Conditional result was False 2025-10-29 00:18:05.111009 | 2025-10-29 00:18:05.111149 | TASK [Register the RHEL node] 2025-10-29 00:18:05.281043 | 2025-10-29 00:18:05.281568 | TASK [Show the subscription-manager status] 2025-10-29 00:18:05.460139 | controller | skipping: Conditional result was False 2025-10-29 00:18:05.467578 | 2025-10-29 00:18:05.467717 | TASK [Enable EPEL on RHEL] 2025-10-29 00:18:05.615960 | controller | skipping: Conditional result was False 2025-10-29 00:18:05.625717 | 2025-10-29 00:18:05.625854 | TASK [Install git and tox] 2025-10-29 00:19:32.574077 | controller | changed 2025-10-29 00:19:32.584924 | 2025-10-29 00:19:32.585060 | TASK [include_role : prepare-workspace] 2025-10-29 00:19:32.623194 | controller | ok 2025-10-29 00:19:32.657457 | 2025-10-29 00:19:32.657582 | TASK [prepare-workspace : Start zuul_console daemon.] 2025-10-29 00:19:33.189803 | controller | ok 2025-10-29 00:19:33.196740 | 2025-10-29 00:19:33.196870 | TASK [prepare-workspace : Synchronize src repos to workspace directory.] 2025-10-29 00:19:47.107604 | controller | Output suppressed because no_log was given 2025-10-29 00:19:47.148492 | 2025-10-29 00:19:47.148603 | TASK [include_role : prepare-workspace-openshift] 2025-10-29 00:19:47.164797 | controller | skipping: Conditional result was False 2025-10-29 00:19:47.188661 | 2025-10-29 00:19:47.188785 | PLAY [all:!appliance] 2025-10-29 00:19:47.206751 | 2025-10-29 00:19:47.206869 | TASK [Run add-build-sshkey role (RSA)] 2025-10-29 00:19:47.226883 | controller | ok 2025-10-29 00:19:47.242778 | 2025-10-29 00:19:47.242882 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-29 00:19:47.501325 | controller -> localhost | ok 2025-10-29 00:19:47.508229 | 2025-10-29 00:19:47.508318 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-29 00:19:47.541213 | controller | ok 2025-10-29 00:19:47.559794 | controller | included: /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-29 00:19:47.566805 | 2025-10-29 00:19:47.566894 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-29 00:19:48.063207 | controller -> localhost | Generating public/private rsa key pair. 2025-10-29 00:19:48.063461 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/work/30ea7e71e4694ac8a7c6d0bc0c1b63ba_id_rsa. 2025-10-29 00:19:48.063493 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/work/30ea7e71e4694ac8a7c6d0bc0c1b63ba_id_rsa.pub. 2025-10-29 00:19:48.063515 | controller -> localhost | The key fingerprint is: 2025-10-29 00:19:48.063535 | controller -> localhost | SHA256:ZmSVsbDB20MUQoJzaQF4RtKJcfWPjXYcYNCb5GkiOhI zuul-build-sshkey 2025-10-29 00:19:48.063557 | controller -> localhost | The key's randomart image is: 2025-10-29 00:19:48.063576 | controller -> localhost | +---[RSA 2048]----+ 2025-10-29 00:19:48.063595 | controller -> localhost | | o*+==BB.=+ | 2025-10-29 00:19:48.063615 | controller -> localhost | | ooB +++Bo. | 2025-10-29 00:19:48.063634 | controller -> localhost | | o + o=Bo | 2025-10-29 00:19:48.063654 | controller -> localhost | |E . .oB*o. | 2025-10-29 00:19:48.063672 | controller -> localhost | | . . . oS =. | 2025-10-29 00:19:48.063724 | controller -> localhost | |. o + . | 2025-10-29 00:19:48.063753 | controller -> localhost | | . . | 2025-10-29 00:19:48.063776 | controller -> localhost | | | 2025-10-29 00:19:48.063797 | controller -> localhost | | | 2025-10-29 00:19:48.063819 | controller -> localhost | +----[SHA256]-----+ 2025-10-29 00:19:48.063871 | controller -> localhost | ok: Runtime: 0:00:00.077626 2025-10-29 00:19:48.071540 | 2025-10-29 00:19:48.071614 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-29 00:19:48.107483 | controller | ok 2025-10-29 00:19:48.136345 | controller | included: /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-29 00:19:48.147966 | 2025-10-29 00:19:48.148079 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-29 00:19:48.173177 | controller | skipping: Conditional result was False 2025-10-29 00:19:48.181201 | 2025-10-29 00:19:48.181342 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-29 00:19:48.855014 | controller | changed 2025-10-29 00:19:48.862174 | 2025-10-29 00:19:48.862288 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-29 00:19:49.210136 | controller | ok 2025-10-29 00:19:49.228822 | 2025-10-29 00:19:49.229028 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-29 00:19:50.566091 | controller | changed 2025-10-29 00:19:50.576493 | 2025-10-29 00:19:50.576631 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-29 00:19:51.866263 | controller | changed 2025-10-29 00:19:51.876440 | 2025-10-29 00:19:51.876587 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-29 00:19:51.903373 | controller | skipping: Conditional result was False 2025-10-29 00:19:51.914336 | 2025-10-29 00:19:51.914488 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-29 00:19:52.353490 | controller -> localhost | changed 2025-10-29 00:19:52.366366 | 2025-10-29 00:19:52.366507 | TASK [add-build-sshkey : Add back temp key] 2025-10-29 00:19:52.636050 | controller -> localhost | Identity added: /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/work/30ea7e71e4694ac8a7c6d0bc0c1b63ba_id_rsa (zuul-build-sshkey) 2025-10-29 00:19:52.636287 | controller -> localhost | ok: Runtime: 0:00:00.010151 2025-10-29 00:19:52.644822 | 2025-10-29 00:19:52.644921 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-29 00:19:53.187146 | controller | ok 2025-10-29 00:19:53.199946 | 2025-10-29 00:19:53.200092 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-29 00:19:53.228097 | controller | skipping: Conditional result was False 2025-10-29 00:19:53.255095 | 2025-10-29 00:19:53.255259 | TASK [Run add-build-sshkey role (ECDSA)] 2025-10-29 00:19:53.289652 | controller | ok 2025-10-29 00:19:53.314276 | 2025-10-29 00:19:53.314803 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build] 2025-10-29 00:19:53.574555 | controller -> localhost | ok 2025-10-29 00:19:53.581513 | 2025-10-29 00:19:53.581646 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID] 2025-10-29 00:19:53.611919 | controller | ok 2025-10-29 00:19:53.623807 | controller | included: /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml 2025-10-29 00:19:53.630811 | 2025-10-29 00:19:53.630880 | TASK [add-build-sshkey : Create Temp SSH key] 2025-10-29 00:19:53.920054 | controller -> localhost | Generating public/private ecdsa key pair. 2025-10-29 00:19:53.920258 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/work/30ea7e71e4694ac8a7c6d0bc0c1b63ba_id_ecdsa. 2025-10-29 00:19:53.920288 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/work/30ea7e71e4694ac8a7c6d0bc0c1b63ba_id_ecdsa.pub. 2025-10-29 00:19:53.920320 | controller -> localhost | The key fingerprint is: 2025-10-29 00:19:53.920342 | controller -> localhost | SHA256:BrSytU4skuXHhtr5wHYDFiYuzQNaWh5WJnPkvVVprjU zuul-build-sshkey 2025-10-29 00:19:53.920362 | controller -> localhost | The key's randomart image is: 2025-10-29 00:19:53.920386 | controller -> localhost | +---[ECDSA 521]---+ 2025-10-29 00:19:53.920406 | controller -> localhost | | o.= . .. | 2025-10-29 00:19:53.920426 | controller -> localhost | | B o . .o | 2025-10-29 00:19:53.920446 | controller -> localhost | |. * * = .o | 2025-10-29 00:19:53.920465 | controller -> localhost | |.@ B O = E | 2025-10-29 00:19:53.920483 | controller -> localhost | |+ O B O So . | 2025-10-29 00:19:53.920502 | controller -> localhost | | . B O .. | 2025-10-29 00:19:53.920521 | controller -> localhost | | . * + | 2025-10-29 00:19:53.920539 | controller -> localhost | | . + . | 2025-10-29 00:19:53.920558 | controller -> localhost | | . | 2025-10-29 00:19:53.920577 | controller -> localhost | +----[SHA256]-----+ 2025-10-29 00:19:53.920626 | controller -> localhost | ok: Runtime: 0:00:00.011046 2025-10-29 00:19:53.929380 | 2025-10-29 00:19:53.929477 | TASK [add-build-sshkey : Remote setup ssh keys (linux)] 2025-10-29 00:19:53.959930 | controller | ok 2025-10-29 00:19:53.967296 | controller | included: /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml 2025-10-29 00:19:53.976919 | 2025-10-29 00:19:53.976993 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey] 2025-10-29 00:19:54.001657 | controller | skipping: Conditional result was False 2025-10-29 00:19:54.008205 | 2025-10-29 00:19:54.008283 | TASK [add-build-sshkey : Enable access via build key on all nodes] 2025-10-29 00:19:54.601910 | controller | changed 2025-10-29 00:19:54.609557 | 2025-10-29 00:19:54.609673 | TASK [add-build-sshkey : Make sure user has a .ssh] 2025-10-29 00:19:54.940584 | controller | ok 2025-10-29 00:19:54.948383 | 2025-10-29 00:19:54.948470 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes] 2025-10-29 00:19:56.305534 | controller | changed 2025-10-29 00:19:56.318131 | 2025-10-29 00:19:56.318274 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes] 2025-10-29 00:19:57.626297 | controller | changed 2025-10-29 00:19:57.639820 | 2025-10-29 00:19:57.639959 | TASK [add-build-sshkey : Remote setup ssh keys (windows)] 2025-10-29 00:19:57.668136 | controller | skipping: Conditional result was False 2025-10-29 00:19:57.684195 | 2025-10-29 00:19:57.684353 | TASK [remove-zuul-sshkey : Remove master key from local agent] 2025-10-29 00:19:57.943212 | controller -> localhost | changed 2025-10-29 00:19:57.991075 | 2025-10-29 00:19:57.991201 | TASK [add-build-sshkey : Add back temp key] 2025-10-29 00:19:58.342035 | controller -> localhost | Identity added: /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/work/30ea7e71e4694ac8a7c6d0bc0c1b63ba_id_ecdsa (zuul-build-sshkey) 2025-10-29 00:19:58.342230 | controller -> localhost | ok: Runtime: 0:00:00.013434 2025-10-29 00:19:58.348794 | 2025-10-29 00:19:58.348862 | TASK [add-build-sshkey : Verify we can still SSH to all nodes] 2025-10-29 00:19:58.721072 | controller | ok 2025-10-29 00:19:58.729291 | 2025-10-29 00:19:58.729419 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)] 2025-10-29 00:19:58.788802 | controller | skipping: Conditional result was False 2025-10-29 00:19:58.808638 | 2025-10-29 00:19:58.808855 | TASK [include_role : remove-zuul-sshkey] 2025-10-29 00:19:58.834454 | controller | skipping: Conditional result was False 2025-10-29 00:19:58.840795 | 2025-10-29 00:19:58.840865 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them] 2025-10-29 00:19:59.177147 | controller | ok: "logs" 2025-10-29 00:19:59.177454 | controller | ok: All items complete 2025-10-29 00:19:59.177494 | 2025-10-29 00:19:59.477614 | controller | ok: "artifacts" 2025-10-29 00:19:59.752976 | controller | ok: "docs" 2025-10-29 00:19:59.776473 | 2025-10-29 00:19:59.776632 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist] 2025-10-29 00:20:00.238850 | controller | changed: "logs" 2025-10-29 00:20:00.552302 | controller | changed: "artifacts" 2025-10-29 00:20:00.876906 | controller | changed: "docs" 2025-10-29 00:20:00.917406 | 2025-10-29 00:20:00.917502 | PLAY RECAP 2025-10-29 00:20:00.917546 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0 2025-10-29 00:20:00.917572 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0 2025-10-29 00:20:00.917591 | 2025-10-29 00:20:01.041386 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master] 2025-10-29 00:20:01.042433 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-29 00:20:01.681489 | 2025-10-29 00:20:01.681614 | PLAY [all] 2025-10-29 00:20:01.703119 | 2025-10-29 00:20:01.703242 | TASK [Install binary dependencies] 2025-10-29 00:20:01.753087 | controller | ok 2025-10-29 00:20:01.772644 | 2025-10-29 00:20:01.772876 | TASK [bindep : Include find tasks] 2025-10-29 00:20:01.812279 | controller | ok 2025-10-29 00:20:01.819910 | controller | included: /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml 2025-10-29 00:20:01.825909 | 2025-10-29 00:20:01.825973 | TASK [bindep : Look for bindep.txt] 2025-10-29 00:20:02.923354 | controller | ok 2025-10-29 00:20:02.933429 | 2025-10-29 00:20:02.933555 | TASK [bindep : Define bindep_file fact] 2025-10-29 00:20:02.960671 | controller | skipping: Conditional result was False 2025-10-29 00:20:02.966823 | 2025-10-29 00:20:02.966912 | TASK [bindep : Look for other-requirements.txt] 2025-10-29 00:20:03.363965 | controller | ok 2025-10-29 00:20:03.369631 | 2025-10-29 00:20:03.369736 | TASK [bindep : Define bindep_file fact] 2025-10-29 00:20:03.393853 | controller | skipping: Conditional result was False 2025-10-29 00:20:03.400990 | 2025-10-29 00:20:03.401067 | TASK [bindep : Look for bindep fallback file] 2025-10-29 00:20:03.435533 | controller | skipping: Conditional result was False 2025-10-29 00:20:03.442836 | 2025-10-29 00:20:03.442923 | TASK [bindep : Define bindep_file fact] 2025-10-29 00:20:03.467187 | controller | skipping: Conditional result was False 2025-10-29 00:20:03.474189 | 2025-10-29 00:20:03.474265 | TASK [bindep : Include bindep tasks] 2025-10-29 00:20:03.498991 | controller | skipping: Conditional result was False 2025-10-29 00:20:03.508196 | 2025-10-29 00:20:03.508294 | TASK [bindep : Include install tasks] 2025-10-29 00:20:03.533255 | controller | skipping: Conditional result was False 2025-10-29 00:20:03.543559 | 2025-10-29 00:20:03.543704 | LOOP [bindep : Include package tasks] 2025-10-29 00:20:03.606282 | 2025-10-29 00:20:03.606499 | TASK [Run test-setup role] 2025-10-29 00:20:03.628995 | controller | ok 2025-10-29 00:20:03.656348 | 2025-10-29 00:20:03.656467 | TASK [test-setup : Check if project's tools/test-setup.sh exists] 2025-10-29 00:20:03.969900 | controller | ok 2025-10-29 00:20:03.978737 | 2025-10-29 00:20:03.978836 | TASK [test-setup : Run tools/test-setup.sh] 2025-10-29 00:20:04.120977 | controller | skipping: Conditional result was False 2025-10-29 00:20:04.146815 | 2025-10-29 00:20:04.146918 | PLAY RECAP 2025-10-29 00:20:04.146967 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-29 00:20:04.146994 | 2025-10-29 00:20:04.261152 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master] 2025-10-29 00:20:04.262071 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-29 00:20:04.906759 | 2025-10-29 00:20:04.906873 | PLAY [controller] 2025-10-29 00:20:04.925880 | 2025-10-29 00:20:04.925972 | TASK [Create the /root directory] 2025-10-29 00:20:05.656794 | controller | ok 2025-10-29 00:20:05.665080 | 2025-10-29 00:20:05.665238 | TASK [Install glibc-langpack-en] 2025-10-29 00:20:13.630958 | controller | ok: Nothing to do 2025-10-29 00:20:13.643790 | 2025-10-29 00:20:13.643942 | TASK [Ensure controller directory exists] 2025-10-29 00:20:14.165376 | controller | changed 2025-10-29 00:20:14.178063 | 2025-10-29 00:20:14.178204 | TASK [Install container runtime] 2025-10-29 00:20:14.270302 | controller | ok 2025-10-29 00:20:14.322866 | 2025-10-29 00:20:14.322989 | LOOP [ensure-podman : Find distribution installation] 2025-10-29 00:20:14.363901 | controller | ok: "/var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml" 2025-10-29 00:20:14.380170 | controller | included: /var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml 2025-10-29 00:20:14.389959 | 2025-10-29 00:20:14.390063 | TASK [ensure-podman : Install podman (RedHat)] 2025-10-29 00:21:26.648152 | controller | changed 2025-10-29 00:21:26.662138 | 2025-10-29 00:21:26.662279 | TASK [ensure-podman : Fetch podman version] 2025-10-29 00:21:28.095388 | controller | Client: Podman Engine 2025-10-29 00:21:28.095493 | controller | Version: 4.6.2 2025-10-29 00:21:28.095535 | controller | API Version: 4.6.2 2025-10-29 00:21:28.095575 | controller | Go Version: go1.19.12 2025-10-29 00:21:28.095633 | controller | Built: Mon Aug 28 19:38:31 2023 2025-10-29 00:21:28.095677 | controller | OS/Arch: linux/amd64 2025-10-29 00:21:28.327310 | controller | ok: Runtime: 0:00:00.196879 2025-10-29 00:21:28.336524 | 2025-10-29 00:21:28.336652 | TASK [ensure-podman : Print podman version installed] 2025-10-29 00:21:28.386889 | Podman version: Client: Podman Engine 2025-10-29 00:21:28.387156 | Version: 4.6.2 2025-10-29 00:21:28.387221 | API Version: 4.6.2 2025-10-29 00:21:28.387270 | Go Version: go1.19.12 2025-10-29 00:21:28.387313 | Built: Mon Aug 28 19:38:31 2023 2025-10-29 00:21:28.387356 | OS/Arch: linux/amd64 2025-10-29 00:21:28.401511 | 2025-10-29 00:21:28.401663 | TASK [ensure-podman : Validate podman engine] 2025-10-29 00:21:28.542724 | controller | skipping: Conditional result was False 2025-10-29 00:21:28.570013 | 2025-10-29 00:21:28.570185 | TASK [ensure-podman : Set up docker compatability socket] 2025-10-29 00:21:28.587534 | controller | skipping: Conditional result was False 2025-10-29 00:21:28.604784 | 2025-10-29 00:21:28.604927 | TASK [Ensure python3.8 is present] 2025-10-29 00:21:28.625259 | controller | skipping: Conditional result was False 2025-10-29 00:21:28.634868 | 2025-10-29 00:21:28.635014 | TASK [Run our-ensure-python role (Fedora only for now)] 2025-10-29 00:21:28.663191 | controller | ok 2025-10-29 00:21:28.681076 | 2025-10-29 00:21:28.681183 | TASK [our-ensure-python : Install the right Python version (rpm)] 2025-10-29 00:21:32.487967 | controller | ok: Nothing to do 2025-10-29 00:21:32.494434 | 2025-10-29 00:21:32.494525 | TASK [our-ensure-python : Also install python3-devel] 2025-10-29 00:21:45.421867 | controller | changed 2025-10-29 00:21:45.438205 | 2025-10-29 00:21:45.438304 | TASK [Run ensure-virtualenv role] 2025-10-29 00:21:45.465301 | controller | ok 2025-10-29 00:21:45.501730 | 2025-10-29 00:21:45.501859 | TASK [ensure-virtualenv : Check if virtualenv is installed] 2025-10-29 00:21:45.922994 | controller | /usr/bin/virtualenv 2025-10-29 00:21:46.142987 | controller | ok: Runtime: 0:00:00.004519 2025-10-29 00:21:46.157721 | 2025-10-29 00:21:46.157887 | LOOP [ensure-virtualenv : Install virtualenv package] 2025-10-29 00:21:46.195475 | controller | skipping: Conditional result was False 2025-10-29 00:21:46.195971 | controller | ok: All items complete 2025-10-29 00:21:46.196038 | 2025-10-29 00:21:46.226202 | 2025-10-29 00:21:46.226418 | TASK [Find the full path of the Python interpreter] 2025-10-29 00:21:46.778570 | controller | /usr/bin/python3 2025-10-29 00:21:46.902126 | controller | ok 2025-10-29 00:21:46.916277 | 2025-10-29 00:21:46.916423 | TASK [Create virtualenv for ansible-test with a specific interpreter] 2025-10-29 00:21:48.442035 | controller | created virtual environment CPython3.11.0.final.0-64 in 766ms 2025-10-29 00:21:48.494431 | controller | creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False) 2025-10-29 00:21:48.495301 | 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-29 00:21:48.495377 | controller | added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1 2025-10-29 00:21:48.495400 | controller | activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator 2025-10-29 00:21:48.572511 | controller | changed 2025-10-29 00:21:48.578922 | 2025-10-29 00:21:48.578997 | TASK [Set selinux package] 2025-10-29 00:21:48.608682 | controller | ok 2025-10-29 00:21:48.613528 | 2025-10-29 00:21:48.613597 | TASK [Set selinux package (Fedora)] 2025-10-29 00:21:48.643600 | controller | ok 2025-10-29 00:21:48.653329 | 2025-10-29 00:21:48.653493 | TASK [Install selinux into virtualenv] 2025-10-29 00:21:51.341564 | controller | Collecting selinux-please-lie-to-me 2025-10-29 00:21:51.440176 | controller | Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB) 2025-10-29 00:21:51.977188 | controller | Collecting setuptools<50.0.0 2025-10-29 00:21:51.990912 | controller | Downloading setuptools-49.6.0-py3-none-any.whl (803 kB) 2025-10-29 00:21:52.129786 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.2 MB/s eta 0:00:00 2025-10-29 00:21:52.284320 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me 2025-10-29 00:21:52.287866 | controller | Attempting uninstall: setuptools 2025-10-29 00:21:52.287928 | controller | Found existing installation: setuptools 62.6.0 2025-10-29 00:21:52.398901 | controller | Uninstalling setuptools-62.6.0: 2025-10-29 00:21:52.414228 | controller | Successfully uninstalled setuptools-62.6.0 2025-10-29 00:21:53.154779 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0 2025-10-29 00:21:53.360893 | controller | 2025-10-29 00:21:53.573348 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-10-29 00:21:53.573393 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-29 00:21:53.828129 | controller | ok: Runtime: 0:00:04.424486 2025-10-29 00:21:53.836158 | 2025-10-29 00:21:53.836324 | TASK [Install pytest-forked into virtualenv] 2025-10-29 00:21:55.069055 | controller | Collecting pytest-forked 2025-10-29 00:21:55.162893 | controller | Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB) 2025-10-29 00:21:55.221529 | controller | Collecting py 2025-10-29 00:21:55.236554 | controller | Downloading py-1.11.0-py2.py3-none-any.whl (98 kB) 2025-10-29 00:21:55.274337 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00 2025-10-29 00:21:55.452600 | controller | Collecting pytest>=3.10 2025-10-29 00:21:55.467842 | controller | Downloading pytest-8.4.2-py3-none-any.whl (365 kB) 2025-10-29 00:21:55.521732 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 7.2 MB/s eta 0:00:00 2025-10-29 00:21:55.578988 | controller | Collecting iniconfig>=1 2025-10-29 00:21:55.594720 | controller | Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB) 2025-10-29 00:21:55.662370 | controller | Collecting packaging>=20 2025-10-29 00:21:55.677173 | controller | Downloading packaging-25.0-py3-none-any.whl (66 kB) 2025-10-29 00:21:55.687414 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.8 MB/s eta 0:00:00 2025-10-29 00:21:55.736373 | controller | Collecting pluggy<2,>=1.5 2025-10-29 00:21:55.779217 | controller | Downloading pluggy-1.6.0-py3-none-any.whl (20 kB) 2025-10-29 00:21:55.852787 | controller | Collecting pygments>=2.7.2 2025-10-29 00:21:55.867843 | controller | Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB) 2025-10-29 00:21:55.965724 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 12.9 MB/s eta 0:00:00 2025-10-29 00:21:56.098243 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked 2025-10-29 00:21:58.360282 | 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-29 00:21:58.376171 | controller | 2025-10-29 00:21:58.555547 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3 2025-10-29 00:21:58.555599 | controller | [notice] To update, run: python -m pip install --upgrade pip 2025-10-29 00:21:58.986853 | controller | ok: Runtime: 0:00:04.209942 2025-10-29 00:21:58.993188 | 2025-10-29 00:21:58.993291 | TASK [Update pip] 2025-10-29 00:22:00.118709 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2) 2025-10-29 00:22:00.413074 | controller | Collecting pip 2025-10-29 00:22:00.525892 | controller | Downloading pip-25.3-py3-none-any.whl (1.8 MB) 2025-10-29 00:22:00.739939 | controller | ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.5 MB/s eta 0:00:00 2025-10-29 00:22:00.899211 | controller | Installing collected packages: pip 2025-10-29 00:22:00.900762 | controller | Attempting uninstall: pip 2025-10-29 00:22:00.905752 | controller | Found existing installation: pip 22.2.2 2025-10-29 00:22:01.175968 | controller | Uninstalling pip-22.2.2: 2025-10-29 00:22:01.205633 | controller | Successfully uninstalled pip-22.2.2 2025-10-29 00:22:03.257998 | controller | Successfully installed pip-25.3 2025-10-29 00:22:03.628058 | controller | ok: Runtime: 0:00:03.926441 2025-10-29 00:22:03.641473 | 2025-10-29 00:22:03.641627 | TASK [Ensure pip temp directory exists in /var/tmp] 2025-10-29 00:22:04.232499 | controller | changed 2025-10-29 00:22:04.252928 | 2025-10-29 00:22:04.253094 | TASK [Install ansible into virtualenv] 2025-10-29 00:22:05.330440 | controller | Processing ./src/github.com/ansible/ansible 2025-10-29 00:22:05.336760 | controller | Installing build dependencies: started 2025-10-29 00:22:07.242342 | controller | Installing build dependencies: finished with status 'done' 2025-10-29 00:22:07.243553 | controller | Getting requirements to build wheel: started 2025-10-29 00:22:08.749334 | controller | Getting requirements to build wheel: finished with status 'done' 2025-10-29 00:22:08.750980 | controller | Preparing metadata (pyproject.toml): started 2025-10-29 00:22:09.667336 | controller | Preparing metadata (pyproject.toml): finished with status 'done' 2025-10-29 00:22:09.672076 | 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-29 00:22:09.676874 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12' 2025-10-29 00:22:09.916861 | controller | ERROR 2025-10-29 00:22:09.917119 | controller | { 2025-10-29 00:22:09.917186 | controller | "delta": "0:00:05.057393", 2025-10-29 00:22:09.917266 | controller | "end": "2025-10-29 00:22:09.822420", 2025-10-29 00:22:09.917310 | controller | "msg": "non-zero return code", 2025-10-29 00:22:09.917392 | controller | "rc": 1, 2025-10-29 00:22:09.917435 | controller | "start": "2025-10-29 00:22:04.765027" 2025-10-29 00:22:09.917474 | controller | } failure 2025-10-29 00:22:09.920394 | 2025-10-29 00:22:09.920497 | PLAY RECAP 2025-10-29 00:22:09.920588 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0 2025-10-29 00:22:09.920635 | 2025-10-29 00:22:10.055124 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master] 2025-10-29 00:22:10.057222 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-29 00:22:10.657266 | 2025-10-29 00:22:10.657397 | PLAY [all] 2025-10-29 00:22:10.678249 | 2025-10-29 00:22:10.678375 | TASK [fetch-subunit-output : Find stestr or testr executable] 2025-10-29 00:22:11.483288 | controller | changed: non-zero return code 2025-10-29 00:22:11.502940 | 2025-10-29 00:22:11.503108 | TASK [fetch-subunit-output : Get the list of directories with subunit files] 2025-10-29 00:22:11.527201 | controller | skipping: Conditional result was False 2025-10-29 00:22:11.534628 | 2025-10-29 00:22:11.534786 | LOOP [fetch-subunit-output : Find any inflight partial subunit files] 2025-10-29 00:22:11.578278 | 2025-10-29 00:22:11.578481 | LOOP [fetch-subunit-output : Copy any inflight subunit files] 2025-10-29 00:22:11.615808 | 2025-10-29 00:22:11.615989 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream] 2025-10-29 00:22:11.640784 | controller | skipping: Conditional result was False 2025-10-29 00:22:11.649803 | 2025-10-29 00:22:11.649901 | LOOP [fetch-subunit-output : Generate subunit file] 2025-10-29 00:22:11.684127 | 2025-10-29 00:22:11.684324 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory] 2025-10-29 00:22:11.709291 | controller | skipping: Conditional result was False 2025-10-29 00:22:11.717712 | 2025-10-29 00:22:11.717816 | TASK [fetch-subunit-output : Remove the temporary file] 2025-10-29 00:22:11.744055 | controller | skipping: Conditional result was False 2025-10-29 00:22:11.752660 | 2025-10-29 00:22:11.752851 | TASK [fetch-subunit-output : Process and fetch subunit results] 2025-10-29 00:22:11.778368 | controller | skipping: Conditional result was False 2025-10-29 00:22:11.823502 | 2025-10-29 00:22:11.823652 | PLAY RECAP 2025-10-29 00:22:11.823758 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0 2025-10-29 00:22:11.823793 | 2025-10-29 00:22:11.936759 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master] 2025-10-29 00:22:11.937644 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master] 2025-10-29 00:22:12.499400 | 2025-10-29 00:22:12.499525 | PLAY [all:!appliance*] 2025-10-29 00:22:12.534636 | 2025-10-29 00:22:12.534746 | TASK [unregister the node] 2025-10-29 00:22:12.666908 | controller | skipping: Conditional result was False 2025-10-29 00:22:12.675448 | 2025-10-29 00:22:12.675556 | TASK [include_role : fetch-output] 2025-10-29 00:22:12.709759 | controller | ok 2025-10-29 00:22:12.737178 | 2025-10-29 00:22:12.737308 | TASK [fetch-output : Set log path for multiple nodes] 2025-10-29 00:22:12.794973 | controller | skipping: Conditional result was False 2025-10-29 00:22:12.802673 | 2025-10-29 00:22:12.802790 | TASK [fetch-output : Set log path for single node] 2025-10-29 00:22:12.870043 | controller | ok 2025-10-29 00:22:12.878170 | 2025-10-29 00:22:12.878267 | LOOP [fetch-output : Ensure local output dirs] 2025-10-29 00:22:13.313565 | controller -> localhost | ok: "/var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/work/logs" 2025-10-29 00:22:13.549221 | controller -> localhost | changed: "/var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/work/artifacts" 2025-10-29 00:22:13.787624 | controller -> localhost | changed: "/var/lib/zuul/builds/30ea7e71e4694ac8a7c6d0bc0c1b63ba/work/docs" 2025-10-29 00:22:13.797616 | 2025-10-29 00:22:13.797738 | LOOP [fetch-output : Collect logs, artifacts and docs] 2025-10-29 00:22:15.092342 | controller | changed: 2025-10-29 00:22:15.092704 | controller | .d..t...... ./ 2025-10-29 00:22:15.092772 | controller | cd+++++++++ controller/ 2025-10-29 00:22:15.092840 | controller | changed: All items complete 2025-10-29 00:22:15.092885 | 2025-10-29 00:22:16.189841 | controller | changed: .d..t...... ./ 2025-10-29 00:22:17.216202 | controller | changed: .d..t...... ./ 2025-10-29 00:22:17.250766 | 2025-10-29 00:22:17.250928 | TASK [include_role : fetch-output-openshift] 2025-10-29 00:22:17.287764 | controller | skipping: Conditional result was False 2025-10-29 00:22:17.303372 | 2025-10-29 00:22:17.303525 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir] 2025-10-29 00:22:17.353452 | controller | skipping: Conditional result was False 2025-10-29 00:22:17.371089 | controller | skipping: Conditional result was False 2025-10-29 00:22:17.418963 | 2025-10-29 00:22:17.419120 | PLAY [localhost] 2025-10-29 00:22:17.438234 | 2025-10-29 00:22:17.438340 | TASK [Run Zuul manifest role] 2025-10-29 00:22:17.458267 | localhost | ok 2025-10-29 00:22:17.472244 | 2025-10-29 00:22:17.472331 | TASK [generate-zuul-manifest : Generate Zuul manifest] 2025-10-29 00:22:17.866799 | localhost | changed 2025-10-29 00:22:17.877220 | 2025-10-29 00:22:17.877358 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul] 2025-10-29 00:22:17.914852 | localhost | ok 2025-10-29 00:22:17.934314 | 2025-10-29 00:22:17.934465 | TASK [Set zuul-log-path fact] 2025-10-29 00:22:17.956476 | localhost | ok 2025-10-29 00:22:17.975735 | 2025-10-29 00:22:17.975861 | TASK [set-zuul-log-path-fact : Set log path for a build] 2025-10-29 00:22:18.006951 | localhost | ok 2025-10-29 00:22:18.019467 | 2025-10-29 00:22:18.019575 | LOOP [Run upload-logs-swift role] 2025-10-29 00:22:18.055856 | localhost | Output suppressed because no_log was given 2025-10-29 00:22:18.092745 | 2025-10-29 00:22:18.092883 | TASK [Set zuul-log-path fact] 2025-10-29 00:22:18.128554 | localhost | skipping: Conditional result was False 2025-10-29 00:22:18.135485 | 2025-10-29 00:22:18.135562 | TASK [upload-logs-swift : Ensure logs are readable before uploading] 2025-10-29 00:22:18.636273 | localhost -> localhost | ok: Runtime: 0:00:00.011077 2025-10-29 00:22:18.649350 | 2025-10-29 00:22:18.649506 | TASK [upload-logs-swift : Upload logs to swift]